[MDEV-13807] mariabackup --apply-log-only does generate redo log by performing rollback and possibly other tasks Created: 2017-09-14  Updated: 2020-08-25  Resolved: 2017-09-16

Status: Closed
Project: MariaDB Server
Component/s: Backup
Affects Version/s: 10.1, 10.1.23, 10.1.26
Fix Version/s: 10.1.27

Type: Bug Priority: Major
Reporter: Andrii Nikitin (Inactive) Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Attachments: File apply-log-only-incr.test     File apply-log-only.test    
Issue Links:
Duplicate
is duplicated by MDEV-13890 mariabackup.xb_compressed_encrypted f... Closed
Problem/Incident
causes MDEV-14333 Mariabackup --apply-log-only crashes ... Closed
is caused by MDEV-9566 Add xtrabackup tool to MariaDB 10.1 Closed
Relates
relates to MDEV-13822 Mariabackup --prepare --incremental s... Closed
relates to MDEV-13797 InnoDB may hang if shutdown is initia... Closed

 Description   

Attached tests (from mariabackup suite) do show that mariabackup 10.1 does rollback of uncommitted transactions despite flag --apply-log-only :

FOUND /Rollback of trx with id / in current_test 
# expect NOT FOUND

10.2 as well as xtrabackup 2.3.9 is not affected: 

NOT FOUND /Rollback of trx with id / in current_test 
# expect NOT FOUND



 Comments   
Comment by Andrii Nikitin (Inactive) [ 2017-09-14 ]

Just for reference this is related sh test and its output in 10.1 vs 2.3.9 https://github.com/AndriiNikitin/mariadb-environs-xtrabackup/blob/master/t/MDEV-13807.sh

10.1.26:

./runsuite.sh m3 _plugin/xtrabackup/t/MDEV-13807.sh 
Checking prerequisites...
 
starting test _plugin/xtrabackup/t/MDEV-13807.sh
 
/usr/bin/xtrabackup
 
/usr/bin/innobackupex
 
/usr/bin/mysql
 
Product=10.1.26
 
Product=based on MariaDB server 10.1.26-MariaDB Linux (x86_64)
 
OS="Ubuntu 16.10"
 
MYSQL_INSTALL_DB set to /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/scripts/mysql_install_db
 
MYSQLD set to /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqld
 
MYSQL set to /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysql
 
MYSQLADMIN set to /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqladmin
 
MYSQLDUMP set to /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqldump
 
attempting to clean previous mysqld instances
 
ls: cannot access '/dev/shm/__var0/mysqld*.pid': No such file or directory
 
 
 
STARTING TEST
 
2017-09-14 19:56:49: bash: Starting server with id=1...
 
2017-09-14 19:56:49: bash: Creating server root directory: /dev/shm/__var0/var1
 
2017-09-14 19:56:49: bash: Creating server temporary directory: /dev/shm/__var0/var1/tmp
 
2017-09-14 19:56:49: bash: Creating server data directory: /dev/shm/__var0/var1/data
 
2017-09-14 19:56:49: bash: Calling mysql_install_db
 
Installing MariaDB/MySQL system tables in '/dev/shm/__var0/var1/data' ...
 
2017-09-14 19:56:49 140382293132864 [Note] /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqld (mysqld 10.1.26-MariaDB) starting as process 3077 ...
 
OK
 
Filling help tables...
 
2017-09-14 19:56:52 140088772339264 [Note] /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqld (mysqld 10.1.26-MariaDB) starting as process 3128 ...
 
OK
 
Creating OpenGIS required SP-s...
 
2017-09-14 19:56:55 139910443025984 [Note] /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqld (mysqld 10.1.26-MariaDB) starting as process 3188 ...
 
OK
 
 
 
To start mysqld at boot time you have to copy
 
support-files/mysql.server to the right place for your system
 
 
 
PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !
 
To do so, start the server, then issue the following commands:
 
 
 
'/home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqladmin' -u root password 'new-password'
 
'/home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqladmin' -u root -h UBINTI password 'new-password'
 
 
 
Alternatively you can run:
 
'/home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysql_secure_installation'
 
 
 
which will also give you the option of removing the test
 
databases and anonymous user created by default.  This is
 
strongly recommended for production servers.
 
 
 
See the MariaDB Knowledgebase at http://mariadb.com/kb or the
 
MySQL manual for more instructions.
 
 
 
You can start the MariaDB daemon with:
 
cd '/home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26' ; /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqld_safe --datadir='/dev/shm/__var0/var1/data'
 
 
 
You can test the MariaDB daemon with mysql-test-run.pl
 
cd '/home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/mysql-test' ; perl mysql-test-run.pl
 
 
 
Please report any problems at http://mariadb.org/jira
 
 
 
The latest information about MariaDB is available at http://mariadb.org/.
 
You can find additional information about the MySQL part at:
 
http://dev.mysql.com
 
Consider joining MariaDB's strong and vibrant community:
 
https://mariadb.org/get-involved/
 
 
 
Starting /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqld --defaults-file=/dev/shm/__var0/var1/my.cnf   
2017-09-14 19:56:58 139996956882496 [Note] /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqld (mysqld 10.1.26-MariaDB) starting as process 3249 ...
 
2017-09-14 19:56:59: bash: Made 1 attempts to connect to server
 
2017-09-14 19:56:59: bash: Server with id=1 has been started on port 20946, socket /dev/shm/__var0/tmp/mysql.sock.U6HnJ3
 
2017-09-14 19:56:59: bash: ===> /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysql --defaults-file=/dev/shm/__var0/var1/my.cnf -e create table test.t select 1
 
2017-09-14 19:56:59: bash: ===> /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysql --defaults-file=/dev/shm/__var0/var1/my.cnf test
 
2017-09-14 19:57:00: bash: ===> /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mariabackup --defaults-file=/dev/shm/__var0/var1/my.cnf --no-version-check --backup --target-dir=/dev/shm/__var0/var1/backup
 
170914 19:57:00 Connecting to MySQL server host: localhost, user: root, password: not set, port: not set, socket: /dev/shm/__var0/tmp/mysql.sock.U6HnJ3
 
Using server version 10.1.26-MariaDB
 
/home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mariabackup based on MariaDB server 10.1.26-MariaDB Linux (x86_64) 
xtrabackup: uses posix_fadvise().
 
xtrabackup: cd to /dev/shm/__var0/var1/data/
 
xtrabackup: open files limit requested 0, set to 1024
 
xtrabackup: using the following InnoDB configuration:
 
xtrabackup:   innodb_data_home_dir = ./
 
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
 
xtrabackup:   innodb_log_group_home_dir = ./
 
xtrabackup:   innodb_log_files_in_group = 2
 
xtrabackup:   innodb_log_file_size = 50331648
 
170914 19:57:00 >> log scanned up to (1625057)
 
xtrabackup: Generating a list of tablespaces
 
170914 19:57:00 [01] Copying ./ibdata1 to /dev/shm/__var0/var1/backup/ibdata1
 
170914 19:57:00 [01]        ...done
 
170914 19:57:00 [01] Copying ./test/t.ibd to /dev/shm/__var0/var1/backup/test/t.ibd
 
170914 19:57:00 [01]        ...done
 
170914 19:57:00 [01] Copying ./mysql/gtid_slave_pos.ibd to /dev/shm/__var0/var1/backup/mysql/gtid_slave_pos.ibd
 
170914 19:57:00 [01]        ...done
 
170914 19:57:00 [01] Copying ./mysql/innodb_index_stats.ibd to /dev/shm/__var0/var1/backup/mysql/innodb_index_stats.ibd
 
170914 19:57:00 [01]        ...done
 
170914 19:57:00 [01] Copying ./mysql/innodb_table_stats.ibd to /dev/shm/__var0/var1/backup/mysql/innodb_table_stats.ibd
 
170914 19:57:00 [01]        ...done
 
170914 19:57:01 >> log scanned up to (1625057)
 
170914 19:57:01 Executing FLUSH NO_WRITE_TO_BINLOG TABLES...
 
170914 19:57:01 Executing FLUSH TABLES WITH READ LOCK...
 
170914 19:57:01 Starting to backup non-InnoDB tables and files
 
170914 19:57:01 [01] Copying ./performance_schema/db.opt to /dev/shm/__var0/var1/backup/performance_schema/db.opt
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./test/t.frm to /dev/shm/__var0/var1/backup/test/t.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/gtid_slave_pos.frm to /dev/shm/__var0/var1/backup/mysql/gtid_slave_pos.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/index_stats.MYD to /dev/shm/__var0/var1/backup/mysql/index_stats.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/index_stats.MYI to /dev/shm/__var0/var1/backup/mysql/index_stats.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/index_stats.frm to /dev/shm/__var0/var1/backup/mysql/index_stats.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/column_stats.MYD to /dev/shm/__var0/var1/backup/mysql/column_stats.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/column_stats.MYI to /dev/shm/__var0/var1/backup/mysql/column_stats.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/column_stats.frm to /dev/shm/__var0/var1/backup/mysql/column_stats.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/table_stats.MYD to /dev/shm/__var0/var1/backup/mysql/table_stats.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/table_stats.MYI to /dev/shm/__var0/var1/backup/mysql/table_stats.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/table_stats.frm to /dev/shm/__var0/var1/backup/mysql/table_stats.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/proxies_priv.MYD to /dev/shm/__var0/var1/backup/mysql/proxies_priv.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/proxies_priv.MYI to /dev/shm/__var0/var1/backup/mysql/proxies_priv.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/proxies_priv.frm to /dev/shm/__var0/var1/backup/mysql/proxies_priv.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/innodb_index_stats.frm to /dev/shm/__var0/var1/backup/mysql/innodb_index_stats.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/innodb_table_stats.frm to /dev/shm/__var0/var1/backup/mysql/innodb_table_stats.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/event.MYD to /dev/shm/__var0/var1/backup/mysql/event.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/event.MYI to /dev/shm/__var0/var1/backup/mysql/event.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/event.frm to /dev/shm/__var0/var1/backup/mysql/event.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/slow_log.CSV to /dev/shm/__var0/var1/backup/mysql/slow_log.CSV
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/slow_log.CSM to /dev/shm/__var0/var1/backup/mysql/slow_log.CSM
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/slow_log.frm to /dev/shm/__var0/var1/backup/mysql/slow_log.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/general_log.CSV to /dev/shm/__var0/var1/backup/mysql/general_log.CSV
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/general_log.CSM to /dev/shm/__var0/var1/backup/mysql/general_log.CSM
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/general_log.frm to /dev/shm/__var0/var1/backup/mysql/general_log.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/procs_priv.MYD to /dev/shm/__var0/var1/backup/mysql/procs_priv.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/procs_priv.MYI to /dev/shm/__var0/var1/backup/mysql/procs_priv.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/procs_priv.frm to /dev/shm/__var0/var1/backup/mysql/procs_priv.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/proc.MYD to /dev/shm/__var0/var1/backup/mysql/proc.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/proc.MYI to /dev/shm/__var0/var1/backup/mysql/proc.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/proc.frm to /dev/shm/__var0/var1/backup/mysql/proc.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone_leap_second.MYD to /dev/shm/__var0/var1/backup/mysql/time_zone_leap_second.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone_leap_second.MYI to /dev/shm/__var0/var1/backup/mysql/time_zone_leap_second.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone_leap_second.frm to /dev/shm/__var0/var1/backup/mysql/time_zone_leap_second.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone_transition_type.MYD to /dev/shm/__var0/var1/backup/mysql/time_zone_transition_type.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone_transition_type.MYI to /dev/shm/__var0/var1/backup/mysql/time_zone_transition_type.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone_transition_type.frm to /dev/shm/__var0/var1/backup/mysql/time_zone_transition_type.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone_transition.MYD to /dev/shm/__var0/var1/backup/mysql/time_zone_transition.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone_transition.MYI to /dev/shm/__var0/var1/backup/mysql/time_zone_transition.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone_transition.frm to /dev/shm/__var0/var1/backup/mysql/time_zone_transition.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone.MYD to /dev/shm/__var0/var1/backup/mysql/time_zone.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone.MYI to /dev/shm/__var0/var1/backup/mysql/time_zone.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone.frm to /dev/shm/__var0/var1/backup/mysql/time_zone.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone_name.MYD to /dev/shm/__var0/var1/backup/mysql/time_zone_name.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone_name.MYI to /dev/shm/__var0/var1/backup/mysql/time_zone_name.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/time_zone_name.frm to /dev/shm/__var0/var1/backup/mysql/time_zone_name.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/help_keyword.MYD to /dev/shm/__var0/var1/backup/mysql/help_keyword.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/help_keyword.MYI to /dev/shm/__var0/var1/backup/mysql/help_keyword.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/help_keyword.frm to /dev/shm/__var0/var1/backup/mysql/help_keyword.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/help_relation.MYD to /dev/shm/__var0/var1/backup/mysql/help_relation.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/help_relation.MYI to /dev/shm/__var0/var1/backup/mysql/help_relation.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/help_relation.frm to /dev/shm/__var0/var1/backup/mysql/help_relation.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/help_category.MYD to /dev/shm/__var0/var1/backup/mysql/help_category.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/help_category.MYI to /dev/shm/__var0/var1/backup/mysql/help_category.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/help_category.frm to /dev/shm/__var0/var1/backup/mysql/help_category.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/help_topic.MYD to /dev/shm/__var0/var1/backup/mysql/help_topic.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/help_topic.MYI to /dev/shm/__var0/var1/backup/mysql/help_topic.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/help_topic.frm to /dev/shm/__var0/var1/backup/mysql/help_topic.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/columns_priv.MYD to /dev/shm/__var0/var1/backup/mysql/columns_priv.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/columns_priv.MYI to /dev/shm/__var0/var1/backup/mysql/columns_priv.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/columns_priv.frm to /dev/shm/__var0/var1/backup/mysql/columns_priv.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/tables_priv.MYD to /dev/shm/__var0/var1/backup/mysql/tables_priv.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/tables_priv.MYI to /dev/shm/__var0/var1/backup/mysql/tables_priv.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/tables_priv.frm to /dev/shm/__var0/var1/backup/mysql/tables_priv.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/servers.MYD to /dev/shm/__var0/var1/backup/mysql/servers.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/servers.MYI to /dev/shm/__var0/var1/backup/mysql/servers.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/servers.frm to /dev/shm/__var0/var1/backup/mysql/servers.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/plugin.MYD to /dev/shm/__var0/var1/backup/mysql/plugin.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/plugin.MYI to /dev/shm/__var0/var1/backup/mysql/plugin.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/plugin.frm to /dev/shm/__var0/var1/backup/mysql/plugin.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/func.MYD to /dev/shm/__var0/var1/backup/mysql/func.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/func.MYI to /dev/shm/__var0/var1/backup/mysql/func.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/func.frm to /dev/shm/__var0/var1/backup/mysql/func.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/roles_mapping.MYD to /dev/shm/__var0/var1/backup/mysql/roles_mapping.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/roles_mapping.MYI to /dev/shm/__var0/var1/backup/mysql/roles_mapping.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/roles_mapping.frm to /dev/shm/__var0/var1/backup/mysql/roles_mapping.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/user.MYD to /dev/shm/__var0/var1/backup/mysql/user.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/user.MYI to /dev/shm/__var0/var1/backup/mysql/user.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/user.frm to /dev/shm/__var0/var1/backup/mysql/user.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/host.MYD to /dev/shm/__var0/var1/backup/mysql/host.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/host.MYI to /dev/shm/__var0/var1/backup/mysql/host.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/host.frm to /dev/shm/__var0/var1/backup/mysql/host.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/db.MYD to /dev/shm/__var0/var1/backup/mysql/db.MYD
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/db.MYI to /dev/shm/__var0/var1/backup/mysql/db.MYI
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying ./mysql/db.frm to /dev/shm/__var0/var1/backup/mysql/db.frm
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 Finished backing up non-InnoDB tables and files
 
170914 19:57:01 [01] Copying aria_log.00000001 to /dev/shm/__var0/var1/backup/aria_log.00000001
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [01] Copying aria_log_control to /dev/shm/__var0/var1/backup/aria_log_control
 
170914 19:57:01 [01]        ...done
 
170914 19:57:01 [00] Writing xtrabackup_binlog_info
 
170914 19:57:01 [00]        ...done
 
170914 19:57:01 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
 
xtrabackup: The latest check point (for incremental): '1616829'
 
xtrabackup: Stopping log copying thread.
 
.170914 19:57:01 >> log scanned up to (1625057)
 
 
 
170914 19:57:01 Executing UNLOCK TABLES
 
170914 19:57:01 All tables unlocked
 
170914 19:57:01 Backup created in directory '/dev/shm/__var0/var1/backup/'
 
MySQL binlog position: filename 'mysql-bin.000004', position '452', GTID of the last change '0-1-61'
 
170914 19:57:01 [00] Writing backup-my.cnf
 
170914 19:57:01 [00]        ...done
 
170914 19:57:01 [00] Writing xtrabackup_info
 
170914 19:57:01 [00]        ...done
 
xtrabackup: Transaction log of lsn (1616829) to (1625057) was copied.
 
170914 19:57:01 completed OK!
 
2017-09-14 19:57:01: bash: ===> /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mariabackup --defaults-file=/dev/shm/__var0/var1/my.cnf --no-version-check --prepare --apply-log-only --target-dir=/dev/shm/__var0/var1/backup
 
/home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mariabackup based on MariaDB server 10.1.26-MariaDB Linux (x86_64) 
xtrabackup: cd to /dev/shm/__var0/var1/backup/
 
xtrabackup: This target seems to be not prepared yet.
 
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(1616829)
 
xtrabackup: using the following InnoDB configuration for recovery:
 
xtrabackup:   innodb_data_home_dir = ./
 
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
 
xtrabackup:   innodb_log_group_home_dir = ./
 
xtrabackup:   innodb_log_files_in_group = 1
 
xtrabackup:   innodb_log_file_size = 2097152
 
xtrabackup: using the following InnoDB configuration for recovery:
 
xtrabackup:   innodb_data_home_dir = ./
 
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
 
xtrabackup:   innodb_log_group_home_dir = ./
 
xtrabackup:   innodb_log_files_in_group = 1
 
xtrabackup:   innodb_log_file_size = 2097152
 
xtrabackup: Starting InnoDB instance for recovery.
 
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
 
InnoDB: Using mutexes to ref count buffer pool pages
 
InnoDB: The InnoDB memory heap is disabled
 
InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
 
InnoDB: Compressed tables use zlib 1.2.3
 
InnoDB: Using SSE crc32 instructions
 
InnoDB: Initializing buffer pool, size = 100.0M
 
InnoDB: Completed initialization of buffer pool
 
InnoDB: Highest supported file format is Barracuda.
 
InnoDB: Starting crash recovery from checkpoint LSN=1616829
 
InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
 
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
 
InnoDB: in total 1 row operations to undo
 
InnoDB: Trx id counter is 2816
 
InnoDB: Starting final batch to recover 9 pages from redo log
 
InnoDB: 128 rollback segment(s) are active.
 
InnoDB: Starting in background the rollback of recovered transactions
 
2017-09-14 19:57:02 7f11677ff700  InnoDB: Rolling back trx with id 2313, 1 rows to undo
 
InnoDB: Rollback of trx with id 2313 completed
 
InnoDB: Rollback of non-prepared transactions completed
 
InnoDB: Waiting for purge to start
 
InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequence number 1625057
 
 
 
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
 
InnoDB: FTS optimize thread exiting.
 
InnoDB: Starting shutdown...
 
InnoDB: Dumping buffer pool(s) not yet started
 
InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
 
InnoDB: Some resources were not cleaned up in shutdown: threads 0, events 17, os_mutexes 16, os_fast_mutexes 33
 
InnoDB: Shutdown completed; log sequence number 1625283
 
170914 19:57:04 completed OK!
 
FAIL Rollback was performed
 
2017-09-14 19:57:04: bash: Killing server with id=1...
 
ERROR 2013 (HY000) at line 3: Lost connection to MySQL server during query
 
inc/common.sh: line 420:  3249 Killed                  ${MYSQLD} ${MYSQLD_ARGS} $*
 
inc/common.sh: line 420:  3332 Killed                  start_uncomitted_transaction
 
[MDEV-13807] (15 sec) (res 1) FAIL

2.3.9

a@UBINTI:~/mariadb-environs$ ./runsuite.sh m3 x0 _plugin/xtrabackup/t/MDEV-13807.sh 
Checking prerequisites...
 
starting test _plugin/xtrabackup/t/MDEV-13807.sh
 
/usr/bin/xtrabackup
 
/usr/bin/innobackupex
 
/usr/bin/mysql
 
Product=10.1.26
 
Product=version 2.3.9 based on MySQL server 5.6.24 Linux (x86_64) (revision id: fde0e3e)
 
OS="Ubuntu 16.10"
 
configure_rest_encryption.sh=NA
 
MYSQL_INSTALL_DB set to /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/scripts/mysql_install_db
 
MYSQLD set to /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqld
 
MYSQL set to /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysql
 
MYSQLADMIN set to /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqladmin
 
MYSQLDUMP set to /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqldump
 
attempting to clean previous mysqld instances
 
ls: cannot access '/dev/shm/__var0/mysqld*.pid': No such file or directory
 
 
 
STARTING TEST
 
2017-09-14 20:01:39: bash: Starting server with id=1...
 
2017-09-14 20:01:39: bash: Creating server root directory: /dev/shm/__var0/var1
 
2017-09-14 20:01:39: bash: Creating server temporary directory: /dev/shm/__var0/var1/tmp
 
2017-09-14 20:01:39: bash: Creating server data directory: /dev/shm/__var0/var1/data
 
2017-09-14 20:01:39: bash: Calling mysql_install_db
 
Installing MariaDB/MySQL system tables in '/dev/shm/__var0/var1/data' ...
 
2017-09-14 20:01:39 140657587549760 [Note] /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqld (mysqld 10.1.26-MariaDB) starting as process 3911 ...
 
OK
 
Filling help tables...
 
2017-09-14 20:01:42 140415557436992 [Note] /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqld (mysqld 10.1.26-MariaDB) starting as process 3940 ...
 
OK
 
Creating OpenGIS required SP-s...
 
2017-09-14 20:01:45 140063298725440 [Note] /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqld (mysqld 10.1.26-MariaDB) starting as process 3970 ...
 
OK
 
 
 
To start mysqld at boot time you have to copy
 
support-files/mysql.server to the right place for your system
 
 
 
PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !
 
To do so, start the server, then issue the following commands:
 
 
 
'/home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqladmin' -u root password 'new-password'
 
'/home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqladmin' -u root -h UBINTI password 'new-password'
 
 
 
Alternatively you can run:
 
'/home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysql_secure_installation'
 
 
 
which will also give you the option of removing the test
 
databases and anonymous user created by default.  This is
 
strongly recommended for production servers.
 
 
 
See the MariaDB Knowledgebase at http://mariadb.com/kb or the
 
MySQL manual for more instructions.
 
 
 
You can start the MariaDB daemon with:
 
cd '/home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26' ; /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqld_safe --datadir='/dev/shm/__var0/var1/data'
 
 
 
You can test the MariaDB daemon with mysql-test-run.pl
 
cd '/home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/mysql-test' ; perl mysql-test-run.pl
 
 
 
Please report any problems at http://mariadb.org/jira
 
 
 
The latest information about MariaDB is available at http://mariadb.org/.
 
You can find additional information about the MySQL part at:
 
http://dev.mysql.com
 
Consider joining MariaDB's strong and vibrant community:
 
https://mariadb.org/get-involved/
 
 
 
Starting /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqld --defaults-file=/dev/shm/__var0/var1/my.cnf   
2017-09-14 20:01:48 139996096685632 [Note] /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysqld (mysqld 10.1.26-MariaDB) starting as process 3998 ...
 
2017-09-14 20:01:49: bash: Made 1 attempts to connect to server
 
2017-09-14 20:01:49: bash: Server with id=1 has been started on port 8509, socket /dev/shm/__var0/tmp/mysql.sock.cFrejV
 
2017-09-14 20:01:49: bash: ===> /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysql --defaults-file=/dev/shm/__var0/var1/my.cnf -e create table test.t select 1
 
2017-09-14 20:01:49: bash: ===> /home/a/mariadb-environs/m3-10.1.26/../_depot/m-tar/10.1.26/bin/mysql --defaults-file=/dev/shm/__var0/var1/my.cnf test
 
2017-09-14 20:01:50: bash: ===> /usr/bin/xtrabackup --defaults-file=/dev/shm/__var0/var1/my.cnf --no-version-check --backup --target-dir=/dev/shm/__var0/var1/backup
 
170914 20:01:50 Connecting to MySQL server host: localhost, user: root, password: not set, port: not set, socket: /dev/shm/__var0/tmp/mysql.sock.cFrejV
 
Using server version 10.1.26-MariaDB
 
/usr/bin/xtrabackup version 2.3.9 based on MySQL server 5.6.24 Linux (x86_64) (revision id: fde0e3e)
 
xtrabackup: uses posix_fadvise().
 
xtrabackup: cd to /dev/shm/__var0/var1/data
 
xtrabackup: open files limit requested 0, set to 1024
 
xtrabackup: using the following InnoDB configuration:
 
xtrabackup:   innodb_data_home_dir = ./
 
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
 
xtrabackup:   innodb_log_group_home_dir = ./
 
xtrabackup:   innodb_log_files_in_group = 2
 
xtrabackup:   innodb_log_file_size = 50331648
 
170914 20:01:50 >> log scanned up to (1625057)
 
xtrabackup: Generating a list of tablespaces
 
170914 20:01:50 [01] Copying ./ibdata1 to /dev/shm/__var0/var1/backup/ibdata1
 
170914 20:01:50 [01]        ...done
 
170914 20:01:50 [01] Copying ./test/t.ibd to /dev/shm/__var0/var1/backup/test/t.ibd
 
170914 20:01:50 [01]        ...done
 
170914 20:01:50 [01] Copying ./mysql/gtid_slave_pos.ibd to /dev/shm/__var0/var1/backup/mysql/gtid_slave_pos.ibd
 
170914 20:01:50 [01]        ...done
 
170914 20:01:50 [01] Copying ./mysql/innodb_index_stats.ibd to /dev/shm/__var0/var1/backup/mysql/innodb_index_stats.ibd
 
170914 20:01:50 [01]        ...done
 
170914 20:01:50 [01] Copying ./mysql/innodb_table_stats.ibd to /dev/shm/__var0/var1/backup/mysql/innodb_table_stats.ibd
 
170914 20:01:50 [01]        ...done
 
170914 20:01:51 >> log scanned up to (1625057)
 
170914 20:01:51 Executing FLUSH NO_WRITE_TO_BINLOG TABLES...
 
170914 20:01:51 Executing FLUSH TABLES WITH READ LOCK...
 
170914 20:01:51 Starting to backup non-InnoDB tables and files
 
170914 20:01:51 [01] Copying ./performance_schema/db.opt to /dev/shm/__var0/var1/backup/performance_schema/db.opt
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./test/t.frm to /dev/shm/__var0/var1/backup/test/t.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/gtid_slave_pos.frm to /dev/shm/__var0/var1/backup/mysql/gtid_slave_pos.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/index_stats.MYD to /dev/shm/__var0/var1/backup/mysql/index_stats.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/index_stats.MYI to /dev/shm/__var0/var1/backup/mysql/index_stats.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/index_stats.frm to /dev/shm/__var0/var1/backup/mysql/index_stats.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/column_stats.MYD to /dev/shm/__var0/var1/backup/mysql/column_stats.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/column_stats.MYI to /dev/shm/__var0/var1/backup/mysql/column_stats.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/column_stats.frm to /dev/shm/__var0/var1/backup/mysql/column_stats.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/table_stats.MYD to /dev/shm/__var0/var1/backup/mysql/table_stats.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/table_stats.MYI to /dev/shm/__var0/var1/backup/mysql/table_stats.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/table_stats.frm to /dev/shm/__var0/var1/backup/mysql/table_stats.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/proxies_priv.MYD to /dev/shm/__var0/var1/backup/mysql/proxies_priv.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/proxies_priv.MYI to /dev/shm/__var0/var1/backup/mysql/proxies_priv.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/proxies_priv.frm to /dev/shm/__var0/var1/backup/mysql/proxies_priv.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/innodb_index_stats.frm to /dev/shm/__var0/var1/backup/mysql/innodb_index_stats.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/innodb_table_stats.frm to /dev/shm/__var0/var1/backup/mysql/innodb_table_stats.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/event.MYD to /dev/shm/__var0/var1/backup/mysql/event.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/event.MYI to /dev/shm/__var0/var1/backup/mysql/event.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/event.frm to /dev/shm/__var0/var1/backup/mysql/event.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/slow_log.CSV to /dev/shm/__var0/var1/backup/mysql/slow_log.CSV
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/slow_log.CSM to /dev/shm/__var0/var1/backup/mysql/slow_log.CSM
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/slow_log.frm to /dev/shm/__var0/var1/backup/mysql/slow_log.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/general_log.CSV to /dev/shm/__var0/var1/backup/mysql/general_log.CSV
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/general_log.CSM to /dev/shm/__var0/var1/backup/mysql/general_log.CSM
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/general_log.frm to /dev/shm/__var0/var1/backup/mysql/general_log.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/procs_priv.MYD to /dev/shm/__var0/var1/backup/mysql/procs_priv.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/procs_priv.MYI to /dev/shm/__var0/var1/backup/mysql/procs_priv.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/procs_priv.frm to /dev/shm/__var0/var1/backup/mysql/procs_priv.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/proc.MYD to /dev/shm/__var0/var1/backup/mysql/proc.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/proc.MYI to /dev/shm/__var0/var1/backup/mysql/proc.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/proc.frm to /dev/shm/__var0/var1/backup/mysql/proc.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone_leap_second.MYD to /dev/shm/__var0/var1/backup/mysql/time_zone_leap_second.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone_leap_second.MYI to /dev/shm/__var0/var1/backup/mysql/time_zone_leap_second.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone_leap_second.frm to /dev/shm/__var0/var1/backup/mysql/time_zone_leap_second.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone_transition_type.MYD to /dev/shm/__var0/var1/backup/mysql/time_zone_transition_type.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone_transition_type.MYI to /dev/shm/__var0/var1/backup/mysql/time_zone_transition_type.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone_transition_type.frm to /dev/shm/__var0/var1/backup/mysql/time_zone_transition_type.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone_transition.MYD to /dev/shm/__var0/var1/backup/mysql/time_zone_transition.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone_transition.MYI to /dev/shm/__var0/var1/backup/mysql/time_zone_transition.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone_transition.frm to /dev/shm/__var0/var1/backup/mysql/time_zone_transition.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone.MYD to /dev/shm/__var0/var1/backup/mysql/time_zone.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone.MYI to /dev/shm/__var0/var1/backup/mysql/time_zone.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone.frm to /dev/shm/__var0/var1/backup/mysql/time_zone.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone_name.MYD to /dev/shm/__var0/var1/backup/mysql/time_zone_name.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone_name.MYI to /dev/shm/__var0/var1/backup/mysql/time_zone_name.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/time_zone_name.frm to /dev/shm/__var0/var1/backup/mysql/time_zone_name.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/help_keyword.MYD to /dev/shm/__var0/var1/backup/mysql/help_keyword.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/help_keyword.MYI to /dev/shm/__var0/var1/backup/mysql/help_keyword.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/help_keyword.frm to /dev/shm/__var0/var1/backup/mysql/help_keyword.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/help_relation.MYD to /dev/shm/__var0/var1/backup/mysql/help_relation.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/help_relation.MYI to /dev/shm/__var0/var1/backup/mysql/help_relation.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/help_relation.frm to /dev/shm/__var0/var1/backup/mysql/help_relation.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/help_category.MYD to /dev/shm/__var0/var1/backup/mysql/help_category.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/help_category.MYI to /dev/shm/__var0/var1/backup/mysql/help_category.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/help_category.frm to /dev/shm/__var0/var1/backup/mysql/help_category.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/help_topic.MYD to /dev/shm/__var0/var1/backup/mysql/help_topic.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/help_topic.MYI to /dev/shm/__var0/var1/backup/mysql/help_topic.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/help_topic.frm to /dev/shm/__var0/var1/backup/mysql/help_topic.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/columns_priv.MYD to /dev/shm/__var0/var1/backup/mysql/columns_priv.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/columns_priv.MYI to /dev/shm/__var0/var1/backup/mysql/columns_priv.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/columns_priv.frm to /dev/shm/__var0/var1/backup/mysql/columns_priv.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/tables_priv.MYD to /dev/shm/__var0/var1/backup/mysql/tables_priv.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/tables_priv.MYI to /dev/shm/__var0/var1/backup/mysql/tables_priv.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/tables_priv.frm to /dev/shm/__var0/var1/backup/mysql/tables_priv.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/servers.MYD to /dev/shm/__var0/var1/backup/mysql/servers.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/servers.MYI to /dev/shm/__var0/var1/backup/mysql/servers.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/servers.frm to /dev/shm/__var0/var1/backup/mysql/servers.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/plugin.MYD to /dev/shm/__var0/var1/backup/mysql/plugin.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/plugin.MYI to /dev/shm/__var0/var1/backup/mysql/plugin.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/plugin.frm to /dev/shm/__var0/var1/backup/mysql/plugin.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/func.MYD to /dev/shm/__var0/var1/backup/mysql/func.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/func.MYI to /dev/shm/__var0/var1/backup/mysql/func.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/func.frm to /dev/shm/__var0/var1/backup/mysql/func.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/roles_mapping.MYD to /dev/shm/__var0/var1/backup/mysql/roles_mapping.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/roles_mapping.MYI to /dev/shm/__var0/var1/backup/mysql/roles_mapping.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/roles_mapping.frm to /dev/shm/__var0/var1/backup/mysql/roles_mapping.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/user.MYD to /dev/shm/__var0/var1/backup/mysql/user.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/user.MYI to /dev/shm/__var0/var1/backup/mysql/user.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/user.frm to /dev/shm/__var0/var1/backup/mysql/user.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/host.MYD to /dev/shm/__var0/var1/backup/mysql/host.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/host.MYI to /dev/shm/__var0/var1/backup/mysql/host.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/host.frm to /dev/shm/__var0/var1/backup/mysql/host.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/db.MYD to /dev/shm/__var0/var1/backup/mysql/db.MYD
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/db.MYI to /dev/shm/__var0/var1/backup/mysql/db.MYI
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 [01] Copying ./mysql/db.frm to /dev/shm/__var0/var1/backup/mysql/db.frm
 
170914 20:01:51 [01]        ...done
 
170914 20:01:51 Finished backing up non-InnoDB tables and files
 
170914 20:01:51 [00] Writing xtrabackup_binlog_info
 
170914 20:01:51 [00]        ...done
 
170914 20:01:51 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
 
xtrabackup: The latest check point (for incremental): '1616829'
 
xtrabackup: Stopping log copying thread.
 
.170914 20:01:51 >> log scanned up to (1625057)
 
 
 
170914 20:01:51 Executing UNLOCK TABLES
 
170914 20:01:51 All tables unlocked
 
170914 20:01:51 Backup created in directory '/dev/shm/__var0/var1/backup/'
 
MySQL binlog position: filename 'mysql-bin.000004', position '452', GTID of the last change '0-1-61'
 
170914 20:01:51 [00] Writing backup-my.cnf
 
170914 20:01:51 [00]        ...done
 
170914 20:01:51 [00] Writing xtrabackup_info
 
170914 20:01:51 [00]        ...done
 
xtrabackup: Transaction log of lsn (1616829) to (1625057) was copied.
 
170914 20:01:51 completed OK!
 
2017-09-14 20:01:51: bash: ===> /usr/bin/xtrabackup --defaults-file=/dev/shm/__var0/var1/my.cnf --no-version-check --prepare --apply-log-only --target-dir=/dev/shm/__var0/var1/backup
 
/usr/bin/xtrabackup version 2.3.9 based on MySQL server 5.6.24 Linux (x86_64) (revision id: fde0e3e)
 
xtrabackup: cd to /dev/shm/__var0/var1/backup/
 
xtrabackup: This target seems to be not prepared yet.
 
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(1616829)
 
xtrabackup: using the following InnoDB configuration for recovery:
 
xtrabackup:   innodb_data_home_dir = ./
 
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
 
xtrabackup:   innodb_log_group_home_dir = ./
 
xtrabackup:   innodb_log_files_in_group = 1
 
xtrabackup:   innodb_log_file_size = 2097152
 
xtrabackup: using the following InnoDB configuration for recovery:
 
xtrabackup:   innodb_data_home_dir = ./
 
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
 
xtrabackup:   innodb_log_group_home_dir = ./
 
xtrabackup:   innodb_log_files_in_group = 1
 
xtrabackup:   innodb_log_file_size = 2097152
 
xtrabackup: Starting InnoDB instance for recovery.
 
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
 
InnoDB: Using atomics to ref count buffer pool pages
 
InnoDB: The InnoDB memory heap is disabled
 
InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
InnoDB: Memory barrier is not used
 
InnoDB: Compressed tables use zlib 1.2.8
 
InnoDB: Using CPU crc32 instructions
 
InnoDB: Initializing buffer pool, size = 100.0M
 
InnoDB: Completed initialization of buffer pool
 
InnoDB: Highest supported file format is Barracuda.
 
InnoDB: Log scan progressed past the checkpoint lsn 1616829
 
InnoDB: Database was not shutdown normally!
 
InnoDB: Starting crash recovery.
 
InnoDB: Reading tablespace information from the .ibd files...
 
InnoDB: Restoring possible half-written data pages 
InnoDB: from the doublewrite buffer...
 
InnoDB: Doing recovery: scanned up to log sequence number 1625057 (0%)
 
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
 
InnoDB: in total 1 row operations to undo
 
InnoDB: Trx id counter is 2816
 
InnoDB: Starting an apply batch of log records to the database...
 
InnoDB: Progress in percent: 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
 
 
 
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
 
InnoDB: Starting shutdown...
 
InnoDB: Shutdown completed; log sequence number 1625057
 
170914 20:01:52 completed OK!
 
PASS It looks no rollback was performed
 
2017-09-14 20:01:52: bash: Killing server with id=1...
 
ERROR 2013 (HY000) at line 3: Lost connection to MySQL server during query
 
inc/common.sh: line 420:  3998 Killed                  ${MYSQLD} ${MYSQLD_ARGS} $*
 
inc/common.sh: line 420:  4044 Killed                  start_uncomitted_transaction
 
TEST FINISHED WITH 0
 
cleaning mysqld instances
 
ls: cannot access '/dev/shm/__var0/mysqld*.pid': No such file or directory
 
[MDEV-13807] (13 sec)  PASS

Comment by Marko Mäkelä [ 2017-09-15 ]

Why Mariabackup 10.2 is not affected

The 10.2 version of Mariabackup never processed any transactions, that is, the --apply-log-only is the default parameter.
MDEV-13466 for Mariabackup 10.2.9 introduced the --export option, which will start up and shut down the normal server, and will perform the rollback.

The bug and fix in Mariabackup 10.1

Percona Xtrabackup 2.3 uses the variable srv_apply_log_only. But, the Mariabackup 10.1 implementation in MDEV-9566 is missing necessary references to this variable in the files srv0start.cc, log0recv.cc, trx0rseg.cc. There are references in srv0srv.h, srv0srv.cc, trx0sys.cc. All these references must correspond to what xtrabackup is doing.

To ensure that further bugs in this class will not go undetected, I think that the following additional code is needed in srv0start.cc, in the appropriate place of innobase_start_or_create_for_mysql():

	ut_d(recv_no_log_write = srv_apply_log_only);

Last but not least, MDEV-11985 introduced an assertion to trx_free_prepared() that would fail on mariabackup --prepare if any recovered transactions exist.
I fixed this in 10.2.9 after seeing the failure on buildbot.
This assertion relaxation must be backported to 10.1. The assertion would not fail in the 10.1 mariabackup --prepare because because of this bug, it would always roll back all recovered transactions.

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