Incremental backup is specific to Mariabackup (and Percona XtraBackup).

I analyzed the trace with the following breakpoints:

(rr) break log0recv.cc:2641

Breakpoint 1 at 0x56304df053d3: file /home/mdbe/MDEV-20755/10.2/storage/innobase/log/log0recv.cc, line 2641.

(rr) cond 1 *space==89&&*page_no==9

(rr) c

…

Thread 1 hit Breakpoint 2, recv_parse_log_rec (type=0x7fff46447aec, 

    ptr=0x563057e3091b ";Y\t\004Y\002\017r\t\002Y\t", 

    end_ptr=0x563057e33b03 "st\001\002t2\002\rcol_varchar_3\003\fn_diff_pfx03\251\002\005", space=0x7fff46447af0, page_no=0x7fff46447af8, apply=false, 

    body=0x7fff46447b00)

    at /home/mdbe/MDEV-20755/10.2/storage/innobase/log/log0recv.cc:2641

2641		const byte*	old_ptr = new_ptr;

(rr) when

Current event: 3168

(rr) p *type

$1 = MLOG_INIT_FILE_PAGE2

(rr) disa 1

(rr) break buf_page_get_low

Breakpoint 2 at 0x56304dd934e3: file /home/mdbe/MDEV-20755/10.2/storage/innobase/buf/buf0buf.cc, line 4229.

(rr) cond 2 page_id.m_space==89&&page_id.m_page_no==9

(rr) c

Continuing.

Thread 1 hit Breakpoint 3, buf_page_get_low (page_id=..., page_size=..., 

    rw_latch=2, guess=0x0, mode=11, 

    file=0x56304e51d5b8 "/home/mdbe/MDEV-20755/10.2/storage/innobase/log/log0recv.cc", line=2485, mtr=0x7fff46447b20, err=0x0)

    at /home/mdbe/MDEV-20755/10.2/storage/innobase/buf/buf0buf.cc:4229

4229	{

(rr) bt

#0  buf_page_get_low (page_id=..., page_size=..., rw_latch=2, guess=0x0, 

    mode=11, 

    file=0x56304e51d5b8 "/home/mdbe/MDEV-20755/10.2/storage/innobase/log/log0recv.cc", line=2485, mtr=0x7fff46447b20, err=0x0)

    at /home/mdbe/MDEV-20755/10.2/storage/innobase/buf/buf0buf.cc:4229

#1  0x000056304df04d74 in recv_apply_hashed_log_recs (last_batch=true)

    at /home/mdbe/MDEV-20755/10.2/storage/innobase/log/log0recv.cc:2485

The MLOG_INIT_FILE_PAGE2 suggests that we should not read the page 89:9. But we are doing exactly that!

InnoDB skips the page creation using redo log because the tablespace has MLOG_INDEX_LOAD lsn for it.

  if (space->enable_lsn)

  {

init_fail:

    fil_space_release(space);

    recv_addr->state = RECV_NOT_PROCESSED;

    return NULL;

  }

So it forces the page to be read from disk. IMO, there is no issue in InnoDB recovery.

(rr) where

#0  backup_optimized_ddl_op (space_id=89) at /home/mdbe/MDEV-20755/10.2/extra/mariabackup/xtrabackup.cc:666

#1  0x00005633b1fbdcc3 in recv_mlog_index_load (space_id=89, page_no=5, lsn=45348417)

    at /home/mdbe/MDEV-20755/10.2/storage/innobase/log/log0recv.cc:2769

#2  0x00005633b1fbe2a9 in recv_parse_log_recs (checkpoint_lsn=0, store=0x7ffe75f6af7c, available_mem=0, apply=false)

    at /home/mdbe/MDEV-20755/10.2/storage/innobase/log/log0recv.cc:2960

#3  0x00005633b1894a3e in xtrabackup_copy_log (start_lsn=45340160, end_lsn=45372928, last=false)

    at /home/mdbe/MDEV-20755/10.2/extra/mariabackup/xtrabackup.cc:2739

#4  0x00005633b1894d3e in xtrabackup_copy_logfile (last=false) at /home/mdbe/MDEV-20755/10.2/extra/mariabackup/xtrabackup.cc:2805

#5  0x00005633b189853c in xtrabackup_backup_func () at /home/mdbe/MDEV-20755/10.2/extra/mariabackup/xtrabackup.cc:4334

#6  0x00005633b189f963 in main_low (argv=0x5633b415bb20) at /home/mdbe/MDEV-20755/10.2/extra/mariabackup/xtrabackup.cc:6492

#7  0x00005633b189f1a9 in main (argc=7, argv=0x7ffe75f6c4d8) at /home/mdbe/MDEV-20755/10.2/extra/mariabackup/xtrabackup.cc:6289

It proves that innodb_log_optimize_ddl is enabled.

Because MDEV-19747 in 10.5 is ignoring the setting innodb_log_optimize_ddl (which is enabled by default in 10.2, 10.3, 10.4), the 10.5 release series should be unaffected by this.

I suspect that the problem is that the function backup_fix_ddl() is not compatible with incremental backup. thiru observed that xtrabackup_apply_delta() was applying changes to this tablespace. Maybe backup_fix_ddl() should have replaced or removed the previously generated .delta files when re-copying the entire data file?

We are also encountering this on version 10.4.14 when using mariabackup as galera SST mode. It would help us to have this bug fixed so we don't have to fall back to rsync or mysqldump as SST mode.

Briefly.

The first page of the tablespace is rewritten during preparing incremental backup because tablespace is "created" instead of opening the existing tablespace, because tablespace id from *.meta file is not equal to the tablespace id of data file in full backup directory.

Detailed.

I have repeated the bug locally with the test, provided by Elena, and done the following analysis.

1) The content of "corrupted" page read by mariabackup during incremental --backup and --prepare is the same. But during --backup the page passes validation, and during --prepare it does not pass.

2) The "corrupted" page is encrypted. In mariabackup if the page is encrypted, buf_page_is_corrupted() is invoked during backup only if --extended_validation option is set. But even if we set the option, buf_page_is_corrupted() returns false on --backup, and true on --prepare. The difference is that during --backup the page is passed to buf_page_is_corrupted() after decryption, but during --prepare the page is not decrypted before it is passed to the function.

3) The page is not decrypted in --prepare because space->crypt_data is NULL. space->crypt_data is NULL because fil_space_read_crypt_data() can't find CRYPT_MAGIC in the first page. So it turned out that the first page of the tablespace after the second --prepare does not contain crypt data, but it does contain it after the first --prepare. What means the first page was rewritten during incremental --prepare.

4) When innodb_log_optimize_ddl is enabled, backup_optimized_ddl_op() callback is invoked when MLOG_INDEX_LOAD is read on incremental --backup. The tablespace is pushed in the special container, and then is treated as a newly created tablespace in backup_fix_ddl(), and re-copied in *.new file. But as this is incremental backup, all copied data files are passed through wf_incremental filter, which creates *.delta file, and copies only the pages with LSN greater then incremental_lsn. So after backup_fix_ddl() is executed there will be *.new.delta file with the only page - "corrupted" page from (2), the file does not contain the first page of the tablespace.

5) When incremental --prepare is executed(the second --prepare in Elena's test), the *.new.delta file is renamed to *.ibd.delta file, and applied as regular *.delta file. It turned out that the first page of the tablespace is rewritten when delta is applied with the following stack trace:

 #0  pfs_os_file_write_func (type=..., name=0x7ffd5d596cb0 "./test/t1.ibd", file=..., buf=0x557322804000, offset=0, n=16384, 

     src_file=0x55731f873190 "./extra/mariabackup/xtrabackup.cc", src_line=4705)

     at ./storage/innobase/include/os0file.ic:413

 #1  0x000055731ed20c98 in xb_space_create_file (path=0x7ffd5d596cb0 "./test/t1.ibd", space_id=255, flags=0, file=0x7ffd5d596380)

     at ./extra/mariabackup/xtrabackup.cc:4704

 #2  0x000055731ed217bf in xb_delta_open_matching_space (dbname=0x7ffd5d5982d0 "test", name=0x7ffd5d5970b0 "t1.ibd", info=..., 

     real_name=0x7ffd5d596cb0 "./test/t1.ibd", real_name_len=512, success=0x7ffd5d5969e6)

     at ./extra/mariabackup/xtrabackup.cc:4897

 #3  0x000055731ed21c0e in xtrabackup_apply_delta (dirname=0x5573203c5e00 <xtrabackup_real_incremental_dir> "/dev/shm/b/mysql-test/var/tmp/backup_1/", 

     dbname=0x7ffd5d5982d0 "test", filename=0x7ffd5d5992b0 "t1.ibd.delta")

     at ./extra/mariabackup/xtrabackup.cc:4991

 #4  0x000055731ed22e8a in xb_process_datadir (path=0x5573203c5e00 <xtrabackup_real_incremental_dir> "/dev/shm/b/mysql-test/var/tmp/backup_1/", 

     suffix=0x55731f878b24 ".delta", func=0x55731ed21811 <xtrabackup_apply_delta(char const*, char const*, char const*, void*)>)

     at ./extra/mariabackup/xtrabackup.cc:5337

 #5  0x000055731ed22f84 in xtrabackup_apply_deltas () at ./extra/mariabackup/xtrabackup.cc:5374

 #6  0x000055731ed244d0 in xtrabackup_prepare_func (argv=0x55732279b6b8)

     at ./extra/mariabackup/xtrabackup.cc:5597

So the new tablespace is "created" instead of opening the existing tablespace because tablespace id from *.meta file(the tablespace id of *.new.delta file, created on (4)) can not be found in fil_system->spaces (fil_space_get_by_id() invoked from xb_delta_open_matching_space() returns NULL).

fil_system->spaces is filled in xb_load_tablespaces() before applying delta's. It iterates data files in full backup directory and fill fil_system->spaces.

So the first page of the tablespace is rewritten during preparing incremental backup because tablespace is "created" instead of opening the existing tablespace, because tablespace id from *.meta file is not equal to the tablespace id of data file in full backup directory.

How to fix?

I see the following variants:

1) I suppose that if tablespace id is changed during incremental backup, all non-zero pages of this tablespace contain new tablespace id, i.e. all non-zero pages were changed during incremental backup, so there is no need to get delta in backup_fix_ddl() for such data files, we could just copy the whole data file as *.new.

2) Check if data file exists in full backup directory in xb_delta_open_matching_space(), then change it's id, and invoke fil_space_create() only for non-existing files.

I failed to create stable test case for it. The test scenario I am trying to implement, is the following:

1) Disable pages flushing.
2) Create table.
3) Make full backup.
4) Insert some data.
5) Star incremental backup.
6) Execute "OPTIMIZE TABLE" just after the tablespace is copied during backup.
7) Finish backup.
8) Prepare full and incremental backup. The latter must fail.

As page 0 is not flushed by the server, it's LSN is 0 just after the table is optimized, and that is why the page is not copied to .delta file during incremental backup, and that is why the tablespace is created during incremental prepare as there is no tablespace with the same id during prepare, and the tablespace is created without CRYPT_MAGIC mark on page 0. I supposed that the following page_is_corrupted() call must fail as it will check crc's for encrypted page which was not decrypted as fil_space_read_crypt_data() invoked on tablespace open does not read crypt data from page 0.

But the test is unstable because the sequence of recv_recover_page() calls for different pages is not specified during recovery, and sometimes fil_parse_write_crypt_data() for page 0 is invoked before page_is_corrupted() for any other page, and the page is decrypted successfully before crc check as crypt data is set correctly for the tablespace in fil_parse_write_crypt_data().

We could insert DBUG_EXECUTE_IF() in fil_parse_write_crypt_data() to avoid space->crypt_data initialization on MLOG_FILE_WRITE_CRYPT_DATA redo record execution to make the test stable.

But I am not sure this is correct because I am not sure that changing any data on some page recovery, which could influence recovery process of the other pages, is correct. It's supposed that pages recovery can be done independently for different pages. So fil_parse_write_crypt_data() call from recv_recover_page() looks very suspicious.

Pushed https://github.com/MariaDB/server/tree/bb-10.2-MDEV-20755-incr-copy-new-files for testing.

There will be conflicts on merging it to 10.4, they are resolved in https://github.com/MariaDB/server/tree/10.4-MDEV-20755-incr-copy-new-files branch. The fix should also be merged in 10.5+ despite the issue does not affect 10.5, because it processes files, created by some DDL during backup, more effectively for incremental backup and prepare. As it is a performance fix only for 10.5, there is no need to merge the test case for it. Besides, the test case will always pass for 10.5+ as ddl log optimization is deprecated for those versions. 10.5 conflicts are resolved here: https://github.com/MariaDB/server/tree/10.5-MDEV-20755-incr-copy-new-files.

The fix was reviewed by wlad.