[MDEV-14545] Backup fails due to MLOG_INDEX_LOAD record - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.2(EOL), 10.3(EOL)
Fix Version/s: 10.2.14, 10.3.6
Component/s: Backup
Labels:
None

Sprint:
5.5.59, 10.1.31, 10.2.13, 10.2.14

Description

This is probably duplicate of ~~MDEV-14420~~, just creating backup - related case anyway.
The assert is shown when table is altered immediately after creation:

2017-11-30 13:54:26 140458257676096 [Note] InnoDB: Ignoring data file 'test/t.ibd' with space ID 5, since the redo log references test/t.ibd with space ID 4.

2017-11-30 13:54:26 0x7fbefc8df740  InnoDB: Assertion failure in file /home/a/env1/m8-10.2/src/storage/innobase/log/log0recv.cc line 2382

InnoDB: Failing assertion: type != MLOG_INDEX_LOAD || srv_operation == SRV_OPERATION_NORMAL

...

/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f5909b6a37a]

mysys/stacktrace.c:268(my_print_stacktrace)[0x5628f4935d7c]

log/log0recv.cc:2381(recv_parse_log_recs)[0x5628f4de489d]

log/log0recv.cc:2910(recv_group_scan_log_recs(log_group_t*, unsigned long, unsigned long*, bool))[0x5628f4de4c45]

log/log0recv.cc:3202(recv_recovery_from_checkpoint_start(unsigned long))[0x5628f4de6768]

srv/srv0start.cc:2243(innobase_start_or_create_for_mysql())[0x5628f4e80889]

mariabackup/xtrabackup.cc:1654(innodb_init)[0x5628f4953485]

mariabackup/xtrabackup.cc:5293(main)[0x5628f4937731]

With following test in mariabackup suite (consider similar test for crash recovery):

#--source include/innodb_page_size.inc

call mtr.add_suppression("InnoDB: New log files created");

let $basedir=$MYSQLTEST_VARDIR/tmp/backup;

let $incremental_dir=$MYSQLTEST_VARDIR/tmp/backup_inc1;

CREATE TABLE t(i INT PRIMARY KEY auto_increment, a int) ENGINE INNODB;

alter table t ENGINE=INNODB;

INSERT INTO t(a) select 1 union select 2 union select 3;

echo # Create full backup , modify table, then create incremental/differential backup;

--disable_result_log

exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf  --backup --target-dir=$basedir;

--enable_result_log

# --source include/restart_mysqld.inc

exec $XTRABACKUP --defaults-file=$MYSQLTEST_VARDIR/my.cnf  --backup --target-dir=$incremental_dir --incremental-basedir=$basedir;

--disable_result_log

echo # Prepare full backup, apply incremental one;

exec $XTRABACKUP --prepare --apply-log-only --target-dir=$basedir;

exec $XTRABACKUP --prepare --target-dir=$basedir --incremental-dir=$incremental_dir ;

let $targetdir=$basedir;

-- source include/restart_and_restore.inc

--enable_result_log

DROP TABLE t;

# Cleanup

rmdir $basedir;

rmdir $incremental_dir;

Full output

# ./mtr xa

Logging: /home/a/env1/m8-10.2/src/mysql-test/mysql-test-run.pl  xa

vardir: /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var

Checking leftover processes...

Removing old var directory...

Creating var directory '/home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var'...

Checking supported features...

MariaDB Version 10.2.12-MariaDB

 - SSL connections supported

Collecting tests...

Installing system database...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT

--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019

main.xa 'innodb'                         [ pass ]   3670

call mtr.add_suppression("InnoDB: New log files created");

CREATE TABLE t(i INT PRIMARY KEY auto_increment, a int) ENGINE INNODB;

alter table t ENGINE=INNODB;

INSERT INTO t(a) select 1 union select 2 union select 3;

# Create full backup , modify table, then create incremental/differential backup

# Prepare full backup, apply incremental one

mariabackup.xa                           [ fail ]

        Test ended at 2017-11-30 13:55:05

CURRENT_TEST: mariabackup.xa

171130 13:55:01 Connecting to MySQL server host: localhost, user: root, password: set, port: 16000, socket: /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/mysqld.1.sock

Using server version 10.2.12-MariaDB-log

/home/a/env1/m8-10.2/bld/extra/mariabackup/mariabackup based on MariaDB server 10.2.12-MariaDB Linux (x86_64)

incremental backup from 1645025 is enabled.

mariabackup: uses posix_fadvise().

mariabackup: cd to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/mysqld.1/data/

mariabackup: open files limit requested 1024, set to 1024

mariabackup: using the following InnoDB configuration:

mariabackup:   innodb_data_home_dir = .

mariabackup:   innodb_data_file_path = ibdata1:12M:autoextend

mariabackup:   innodb_log_group_home_dir = ./

2017-11-30 13:55:01 140553722062656 [Note] InnoDB: Number of pools: 1

171130 13:55:01 >> log scanned up to (1645034)

mariabackup: Generating a list of tablespaces

2017-11-30 13:55:01 140553722062656 [Warning] InnoDB: Allocated tablespace ID 1 for mysql/innodb_table_stats, old maximum was 0

mariabackup: using the full scan for incremental backup

171130 13:55:01 [01] Copying ./ibdata1 to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/ibdata1.delta

171130 13:55:01 [01]        ...done

171130 13:55:01 [01] Copying ./mysql/innodb_table_stats.ibd to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/innodb_table_stats.ibd.delta

171130 13:55:01 [01]        ...done

171130 13:55:01 [01] Copying ./mysql/innodb_index_stats.ibd to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/innodb_index_stats.ibd.delta

171130 13:55:01 [01]        ...done

171130 13:55:01 [01] Copying ./test/t.ibd to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/test/t.ibd.delta

171130 13:55:01 [01]        ...done

171130 13:55:02 >> log scanned up to (1645069)

171130 13:55:02 Executing FLUSH NO_WRITE_TO_BINLOG TABLES...

171130 13:55:02 Executing FLUSH TABLES WITH READ LOCK...

171130 13:55:02 Starting to backup non-InnoDB tables and files

171130 13:55:02 [01] Copying ./mysql/db.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/db.frm

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/db.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/db.MYI

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/db.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/db.MYD

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/host.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/host.frm

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/host.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/host.MYI

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/host.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/host.MYD

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/user.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/user.frm

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/user.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/user.MYI

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/user.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/user.MYD

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/roles_mapping.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/roles_mapping.frm

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/roles_mapping.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/roles_mapping.MYI

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/roles_mapping.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/roles_mapping.MYD

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/func.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/func.frm

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/func.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/func.MYI

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/func.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/func.MYD

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/plugin.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/plugin.frm

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/plugin.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/plugin.MYI

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/plugin.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/plugin.MYD

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/servers.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/servers.frm

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/servers.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/servers.MYI

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/servers.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/servers.MYD

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/tables_priv.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/tables_priv.frm

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/tables_priv.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/tables_priv.MYI

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/tables_priv.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/tables_priv.MYD

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/columns_priv.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/columns_priv.frm

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/columns_priv.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/columns_priv.MYI

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/columns_priv.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/columns_priv.MYD

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/help_topic.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/help_topic.frm

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/help_topic.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/help_topic.MYI

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/help_topic.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/help_topic.MYD

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/help_category.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/help_category.frm

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/help_category.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/help_category.MYI

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/help_category.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/help_category.MYD

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/help_relation.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/help_relation.frm

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/help_relation.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/help_relation.MYI

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/help_relation.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/help_relation.MYD

171130 13:55:02 [01]        ...done

171130 13:55:02 [01] Copying ./mysql/help_keyword.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/help_keyword.frm

171130 13:55:02 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/help_keyword.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/help_keyword.MYI

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/help_keyword.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/help_keyword.MYD

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone_name.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone_name.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone_name.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone_name.MYI

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone_name.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone_name.MYD

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone.MYI

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone.MYD

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone_transition.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone_transition.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone_transition.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone_transition.MYI

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone_transition.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone_transition.MYD

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone_transition_type.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone_transition_type.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone_transition_type.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone_transition_type.MYI

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone_transition_type.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone_transition_type.MYD

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone_leap_second.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone_leap_second.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone_leap_second.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone_leap_second.MYI

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/time_zone_leap_second.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/time_zone_leap_second.MYD

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/proc.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/proc.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/proc.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/proc.MYI

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/proc.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/proc.MYD

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/procs_priv.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/procs_priv.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/procs_priv.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/procs_priv.MYI

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/procs_priv.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/procs_priv.MYD

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/general_log.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/general_log.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/general_log.CSM to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/general_log.CSM

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/general_log.CSV to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/general_log.CSV

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/slow_log.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/slow_log.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/slow_log.CSM to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/slow_log.CSM

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/slow_log.CSV to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/slow_log.CSV

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/event.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/event.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/event.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/event.MYI

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/event.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/event.MYD

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/innodb_table_stats.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/innodb_table_stats.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/innodb_index_stats.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/innodb_index_stats.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/proxies_priv.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/proxies_priv.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/proxies_priv.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/proxies_priv.MYI

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/proxies_priv.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/proxies_priv.MYD

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/table_stats.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/table_stats.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/table_stats.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/table_stats.MYI

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/table_stats.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/table_stats.MYD

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/column_stats.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/column_stats.frm

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/column_stats.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/column_stats.MYI

171130 13:55:03 [01]        ...done

171130 13:55:03 [01] Copying ./mysql/column_stats.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/column_stats.MYD

171130 13:55:03 [01]        ...done

171130 13:55:04 [01] Copying ./mysql/index_stats.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/index_stats.frm

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mysql/index_stats.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/index_stats.MYI

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mysql/index_stats.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/index_stats.MYD

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mysql/gtid_slave_pos.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/gtid_slave_pos.MYI

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mysql/gtid_slave_pos.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/gtid_slave_pos.MYD

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mysql/gtid_slave_pos.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mysql/gtid_slave_pos.frm

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./test/t.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/test/t.frm

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./performance_schema/db.opt to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/performance_schema/db.opt

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mtr/db.opt to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mtr/db.opt

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mtr/test_suppressions.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mtr/test_suppressions.frm

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mtr/test_suppressions.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mtr/test_suppressions.MYI

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mtr/test_suppressions.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mtr/test_suppressions.MYD

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mtr/ts_insert.TRN to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mtr/ts_insert.TRN

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mtr/test_suppressions.TRG to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mtr/test_suppressions.TRG

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mtr/global_suppressions.frm to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mtr/global_suppressions.frm

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mtr/global_suppressions.MYI to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mtr/global_suppressions.MYI

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mtr/global_suppressions.MYD to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mtr/global_suppressions.MYD

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mtr/gs_insert.TRN to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mtr/gs_insert.TRN

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying ./mtr/global_suppressions.TRG to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/mtr/global_suppressions.TRG

171130 13:55:04 [01]        ...done

171130 13:55:04 Finished backing up non-InnoDB tables and files

171130 13:55:04 [01] Copying aria_log_control to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/aria_log_control

171130 13:55:04 [01]        ...done

171130 13:55:04 [01] Copying aria_log.00000001 to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/aria_log.00000001

171130 13:55:04 [01]        ...done

171130 13:55:04 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...

mariabackup: The latest check point (for incremental): '1645069'

mariabackup: Stopping log copying thread.

171130 13:55:04 >> log scanned up to (1645078)

171130 13:55:04 Executing UNLOCK TABLES

171130 13:55:04 All tables unlocked

171130 13:55:04 [00] Copying ib_buffer_pool to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/ib_buffer_pool

171130 13:55:04 [00]        ...done

171130 13:55:04 Backup created in directory '/home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup_inc1/'

171130 13:55:04 [00] Writing backup-my.cnf

171130 13:55:04 [00]        ...done

171130 13:55:04 [00] Writing xtrabackup_info

171130 13:55:04 [00]        ...done

mariabackup: Redo log (from LSN 1645034 to 1645078) was copied.

171130 13:55:04 completed OK!

sh: line 1:  4883 Aborted                 (core dumped) /home/a/env1/m8-10.2/bld/extra/mariabackup/mariabackup --prepare --apply-log-only --target-dir=/home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup 2>&1

mysqltest: At line 25: exec of '/home/a/env1/m8-10.2/bld/extra/mariabackup/mariabackup --prepare --apply-log-only --target-dir=/home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup 2>&1' failed, error: 34304, status: 134, errno: 11

Output from before failure:

/home/a/env1/m8-10.2/bld/extra/mariabackup/mariabackup based on MariaDB server 10.2.12-MariaDB Linux (x86_64)

mariabackup: cd to /home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/tmp/backup/

mariabackup: This target seems to be not prepared yet.

mariabackup: using the following InnoDB configuration for recovery:

mariabackup:   innodb_data_home_dir = .

mariabackup:   innodb_data_file_path = ibdata1:12M:autoextend

mariabackup:   innodb_log_group_home_dir = .

mariabackup: Starting InnoDB instance for recovery.

mariabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)

2017-11-30 13:55:04 140020424640320 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2017-11-30 13:55:04 140020424640320 [Note] InnoDB: Uses event mutexes

2017-11-30 13:55:04 140020424640320 [Note] InnoDB: Compressed tables use zlib 1.2.11

2017-11-30 13:55:04 140020424640320 [Note] InnoDB: Number of pools: 1

2017-11-30 13:55:04 140020424640320 [Note] InnoDB: Using SSE2 crc32 instructions

2017-11-30 13:55:04 140020424640320 [Note] InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M

2017-11-30 13:55:04 140020424640320 [Note] InnoDB: Completed initialization of buffer pool

2017-11-30 13:55:04 140020119742208 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().

2017-11-30 13:55:04 140020424640320 [Note] InnoDB: Highest supported file format is Barracuda.

2017-11-30 13:55:04 140020424640320 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1633766

2017-11-30 13:55:04 140020424640320 [Note] InnoDB: Ignoring data file 'test/t.ibd' with space ID 5, since the redo log references test/t.ibd with space ID 4.

2017-11-30 13:55:04 0x7f590bac0740  InnoDB: Assertion failure in file /home/a/env1/m8-10.2/src/storage/innobase/log/log0recv.cc line 2382

InnoDB: Failing assertion: type != MLOG_INDEX_LOAD || srv_operation == SRV_OPERATION_NORMAL

InnoDB: We intentionally generate a memory trap.

InnoDB: Submit a detailed bug report to https://jira.mariadb.org/

InnoDB: If you get repeated assertion failures or crashes, even

InnoDB: immediately after the mysqld startup, there may be

InnoDB: corruption in the InnoDB tablespace. Please refer to

InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html

InnoDB: about forcing recovery.

171130 13:55:04 [ERROR] mysqld got signal 6 ;

This could be because you hit a bug. It is also possible that this binary

or one of the libraries it was linked against is corrupt, improperly built,

or misconfigured. This error can also be caused by malfunctioning hardware.

To report this bug, see https://mariadb.com/kb/en/reporting-bugs

We will try our best to scrape up some info that will hopefully help

diagnose the problem, but since we have already crashed,

something is definitely wrong and this may fail.

Server version: 10.2.12-MariaDB

key_buffer_size=0

read_buffer_size=131072

max_used_connections=0

max_threads=1

thread_count=0

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 5420 K  bytes of memory

Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0

Attempting backtrace. You can use the following information to find out

where mysqld died. If you see no messages after this, something went

terribly wrong...

stack_bottom = 0x0 thread_stack 0x49000

/home/a/env1/m8-10.2/bld/extra/mariabackup/mariabackup(my_print_stacktrace+0x29)[0x5628f503a079]

/home/a/env1/m8-10.2/bld/extra/mariabackup/mariabackup(handle_fatal_signal+0x3bd)[0x5628f4bd4f2d]

/lib/x86_64-linux-gnu/libpthread.so.0(+0x11670)[0x7f590b6ba670]

/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x9f)[0x7f5909b6877f]

/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f5909b6a37a]

mysys/stacktrace.c:268(my_print_stacktrace)[0x5628f4935d7c]

log/log0recv.cc:2381(recv_parse_log_recs)[0x5628f4de489d]

log/log0recv.cc:2910(recv_group_scan_log_recs(log_group_t*, unsigned long, unsigned long*, bool))[0x5628f4de4c45]

log/log0recv.cc:3202(recv_recovery_from_checkpoint_start(unsigned long))[0x5628f4de6768]

srv/srv0start.cc:2243(innobase_start_or_create_for_mysql())[0x5628f4e80889]

mariabackup/xtrabackup.cc:1654(innodb_init)[0x5628f4953485]

mariabackup/xtrabackup.cc:5293(main)[0x5628f4937731]

/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1)[0x7f5909b533f1]

/home/a/env1/m8-10.2/bld/extra/mariabackup/mariabackup(_start+0x2a)[0x5628f494c0da]

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains

information that should help you find out what is causing the crash.

 - saving '/home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/log/mariabackup.xa/' to '/home/a/env1/_depot/m-branch/m8-10.2-bld/mysql-test/var/log/mariabackup.xa/'

--------------------------------------------------------------------------

The servers were restarted 1 times

Spent 3.670 of 23 seconds executing testcases

Failure: Failed 1/2 tests, 50.00% were successful.

Failing test(s): mariabackup.xa

The log files in var/log may give you some hint of what went wrong.

If you want to report this error, please read first the documentation

at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html

mysql-test-run: *** ERROR: there were failing test cases

Attachments

Issue Links

blocks

MDEV-14425 Change the InnoDB redo log format to reduce write amplification

Closed

causes

MDEV-15682 mariabackup.unsupported_redo fails in buildbot with wrong result code

Closed

MDEV-15737 assertion in mariabackup.exe!recv_calc_lsn_on_data_add()

Closed

is duplicated by

MDEV-15625 Mariabackup cannot prepare backup

Closed

MDEV-19322 mariabackup gets an InnoDB assertion failure

Closed

relates to

MDEV-13563 lock DDL for mariabackup in 10.2+

Closed

MDEV-13564 TRUNCATE TABLE and undo tablespace truncation are not compatible with Mariabackup

Closed

MDEV-16809 Allow full redo logging for ALTER TABLE

Closed

MDEV-14420 [Draft] Assertion failure in file /data/src/10.3-bug/storage/innobase/log/log0recv.cc line 1186

Closed

(4 relates to)

Activity

Ascending order - Click to sort in descending order

View 8 older comments

Marko Mäkelä added a comment - 2018-02-02 06:53

Apart from the MLOG_INDEX_LOAD record that informs that ALGORITHM=INPLACE disabled redo logging, there is another MySQL 5.7 change that can ruin a backup.

As reported in ~~MDEV-13564~~, TRUNCATE TABLE will use some extra logging, and crash recovery will rely on the fact that it does an extra redo log checkpoint to clear the head of the redo log. But, Mariabackup will not observe this checkpoint; it instead assumes that it can copy and apply the whole log since the checkpoint that was the latest when the backup operation started.

As part of this fix (making --backup abort if a MLOG_INDEX_LOAD record is present in the log), I think that we should also try to detect TRUNCATE TABLE in the log, if it is doable. The record to look for is MLOG_FILE_CREATE2. This record would be emitted by fil_ibd_create(), which appears to be called both by CREATE TABLE and TRUNCATE TABLE. Because the mini-transaction consists of this single record, and because other threads could add mini-transactions in between, it could be hard to reliably distinguish TRUNCATE from CREATE TABLE.

Marko Mäkelä added a comment - 2018-02-02 06:53 Apart from the MLOG_INDEX_LOAD record that informs that ALGORITHM=INPLACE disabled redo logging, there is another MySQL 5.7 change that can ruin a backup. As reported in MDEV-13564 , TRUNCATE TABLE will use some extra logging, and crash recovery will rely on the fact that it does an extra redo log checkpoint to clear the head of the redo log. But, Mariabackup will not observe this checkpoint; it instead assumes that it can copy and apply the whole log since the checkpoint that was the latest when the backup operation started. As part of this fix (making --backup abort if a MLOG_INDEX_LOAD record is present in the log), I think that we should also try to detect TRUNCATE TABLE in the log, if it is doable. The record to look for is MLOG_FILE_CREATE2 . This record would be emitted by fil_ibd_create() , which appears to be called both by CREATE TABLE and TRUNCATE TABLE . Because the mini-transaction consists of this single record, and because other threads could add mini-transactions in between, it could be hard to reliably distinguish TRUNCATE from CREATE TABLE .

Thirunarayanan Balathandayuthapani added a comment - 2018-03-09 13:14 - edited

Yes, I added it to current sprint.

Thirunarayanan Balathandayuthapani added a comment - 2018-03-09 13:14 - edited Yes, I added it to current sprint.

Thirunarayanan Balathandayuthapani added a comment - 2018-03-10 07:06

https://github.com/MariaDB/server/commit/70199cf21152f35012d4ae7c8b37d2f13133e474

markoCan you please review ?

Thirunarayanan Balathandayuthapani added a comment - 2018-03-10 07:06 https://github.com/MariaDB/server/commit/70199cf21152f35012d4ae7c8b37d2f13133e474 marko Can you please review ?

Marko Mäkelä added a comment - 2018-03-12 09:00

OK to push after addressing my review comments.
I think that we can report the file name related to the first encountered MLOG_INDEX_LOAD record.

Marko Mäkelä added a comment - 2018-03-12 09:00 OK to push after addressing my review comments. I think that we can report the file name related to the first encountered MLOG_INDEX_LOAD record.

Marko Mäkelä added a comment - 2018-03-16 14:15

The fix is introducing a memory leak to mariabackup, which can be observed in a cmake -DWITH_ASAN=1 build:

./mtr --mem mariabackup.unsupported_redo

Direct leak of 72 byte(s) in 1 object(s) allocated from:

    #0 0x7fc903aecc20 in __interceptor_malloc (/lib/x86_64-linux-gnu/libasan.so.4+0xd9c20)

    #1 0x5565a8fb8982 in datafiles_iter_new /mariadb/10.2-ext/extra/mariabackup/xtrabackup.cc:380

    #2 0x5565a8fb90b3 in backup_includes /mariadb/10.2-ext/extra/mariabackup/xtrabackup.cc:461

    #3 0x5565aa23baf1 in recv_parse_log_recs(unsigned long, store_t, bool) /mariadb/10.2-ext/storage/innobase/log/log0recv.cc:2460

    #4 0x5565a8fbfa07 in xtrabackup_copy_log /mariadb/10.2-ext/extra/mariabackup/xtrabackup.cc:2422

    #5 0x5565a8fc013e in xtrabackup_copy_logfile /mariadb/10.2-ext/extra/mariabackup/xtrabackup.cc:2490

    #6 0x5565a8fc68c3 in xtrabackup_backup_func /mariadb/10.2-ext/extra/mariabackup/xtrabackup.cc:3910

    #7 0x5565a8fcf5f6 in main_low /mariadb/10.2-ext/extra/mariabackup/xtrabackup.cc:5575

    #8 0x5565a8fcea17 in main /mariadb/10.2-ext/extra/mariabackup/xtrabackup.cc:5378

    #9 0x7fc9020cca86 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x21a86)

With memory leak checks disabled, the test does pass:

ASAN_OPTIONS=detect_leaks=0,abort_on_error=1 ./mtr --mem mariabackup.unsupported_redo

Marko Mäkelä added a comment - 2018-03-16 14:15 The fix is introducing a memory leak to mariabackup, which can be observed in a cmake -DWITH_ASAN=1 build: ./mtr --mem mariabackup.unsupported_redo Direct leak of 72 byte(s) in 1 object(s) allocated from: #0 0x7fc903aecc20 in __interceptor_malloc (/lib/x86_64-linux-gnu/libasan.so.4+0xd9c20) #1 0x5565a8fb8982 in datafiles_iter_new /mariadb/10.2-ext/extra/mariabackup/xtrabackup.cc:380 #2 0x5565a8fb90b3 in backup_includes /mariadb/10.2-ext/extra/mariabackup/xtrabackup.cc:461 #3 0x5565aa23baf1 in recv_parse_log_recs(unsigned long, store_t, bool) /mariadb/10.2-ext/storage/innobase/log/log0recv.cc:2460 #4 0x5565a8fbfa07 in xtrabackup_copy_log /mariadb/10.2-ext/extra/mariabackup/xtrabackup.cc:2422 #5 0x5565a8fc013e in xtrabackup_copy_logfile /mariadb/10.2-ext/extra/mariabackup/xtrabackup.cc:2490 #6 0x5565a8fc68c3 in xtrabackup_backup_func /mariadb/10.2-ext/extra/mariabackup/xtrabackup.cc:3910 #7 0x5565a8fcf5f6 in main_low /mariadb/10.2-ext/extra/mariabackup/xtrabackup.cc:5575 #8 0x5565a8fcea17 in main /mariadb/10.2-ext/extra/mariabackup/xtrabackup.cc:5378 #9 0x7fc9020cca86 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x21a86) With memory leak checks disabled, the test does pass: ASAN_OPTIONS=detect_leaks=0,abort_on_error=1 ./mtr --mem mariabackup.unsupported_redo

People

Assignee:: Thirunarayanan Balathandayuthapani

Reporter:: Andrii Nikitin (Inactive)

Votes:: 0 Vote for this issue

Watchers:: 6 Start watching this issue

Dates

Created:: 2017-11-30 12:59

Updated:: 2024-07-08 00:24

Resolved:: 2018-03-13 10:13

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server