Following "--prepare" is running like a first time every time

We have
xtrabackup version 8.0.22-15 based on MySQL server 8.0.22 Linux (x86_64) (revision id: fea8a0e)
and mysql Ver 8.0.21 for Linux on x86_64 (Source distribution)

when I run “–prepare” on the taken backup it runs like a first time.
According to the documentation it supposed to say: “This target seems to be already prepared.”

Can you please provide the entire command? So us the exact commands and steps please.

this is the command to backup:

xtrabackup --user=bkpuser --password=PASSWORD --backup --databases='mysql sys performance_schema DB-NAME --target-dir=/var/lib/backup/DB-NAME-backup

To prepare I tried both:

xtrabackup --user=bkpuser --password=PASSWORD --prepare --target-dir=/var/lib/backup/DB-NAME-backup

and

xtrabackup --prepare --target-dir=/var/lib/backup/DB-NAME-backup

You should only run --prepare one time. To clarify, you are running --prepare one time and when you do, it says it is already prepared?
I notice you are using --databases flag. If you want to backup all databases, simply remove this flag completely. XB backs up all databases by default.

I understand that I need to run it only one time.
I run it second time to confirm that it’s all prepared and looking for the message that it is already prepared. But I do no have this message, I have bunch of outputs like preparation is happening again.
I am using --database flag to backup only one database.

Running --prepare more than 1 time can be considered dangerous and is not advised. After running the first time, if everything went fine, you will see ‘Completed OK’ and a result code of 0.

Thank you for clarifying that my situation can be considered as “dangerous”. That’s why I am trying to get help here.
This is from the documentation:

"When this finishes, you should see an InnoDB shutdown with a message such as the following, where again the value of LSN will depend on your system:

InnoDB: Shutdown completed; log sequence number 137345046 160906 11:21:01 completed OK!

All following prepares will not change the already prepared data files, you’ll see that output says:

xtrabackup: This target seems to be already prepared. xtrabackup: notice: xtrabackup_logfile was already used to ‘–prepare’."

In my case I never see the message “xtrabackup: This target seems to be already prepared…”

Here is what I see:

Tue Jan 12 03:34:46 PST 2021

# xtrabackup  --prepare --target-dir=/var/lib/backup/DB-name-backup
...
FTS optimize thread exiting.
Trying to access missing tablespace 4294967294
Starting shutdown...
Log background threads are being closed...
Shutdown completed; log sequence number 62760568332
210112 03:35:30 completed OK!
#echo $#
0

Tue Jan 12 03:36:12 PST 2021

# xtrabackup  --prepare --target-dir=/var/lib/backup/DB-name-backup
...
FTS optimize thread exiting.
Trying to access missing tablespace 4294967294
Starting shutdown...
Log background threads are being closed...
Shutdown completed; log sequence number 62760568332
210112 03:36:41 completed OK!
#echo $#
0

It is like the “xtrabackup” cannot understand that data is already prepared and runs preparation again. Which as you said “is dangerous”

I just attempted this.

xtrabackup --backup --databases='world' --target-dir=/tmp/world-backup
...
210112 22:24:28 completed OK!

xtrabackup --prepare --target-dir /tmp/world-backup
...
xtrabackup: This target seems to be not prepared yet.
...
The log sequence number 34755546567 in the system tablespace does not match the log sequence number 61516344073 in the ib_logfiles!
Database was not shutdown normally!
Starting crash recovery.
Starting to parse redo log at lsn = 61516343823, whereas checkpoint_lsn = 61516344073
Doing recovery: scanned up to log sequence number 61516344103
...
210112 22:24:59 completed OK!

And then prepare again:

xtrabackup --prepare --target-dir /tmp/world-backup
...
xtrabackup: This target seems to be already prepared.  (about 6th line from top)
Number of pools: 1
xtrabackup: notice: xtrabackup_logfile was already used to '--prepare'.
...
210112 22:25:06 completed OK!

I noticed that xtrabackup does not repeat the crash recovery aspect when ran a second time. The second run only re-creates the undo spaces. It appears this is now safe in 8.0.

@matthewb whatever result you posted is how it supposed to be. It’s in par with documentation.
My results are different, I do not see

xtrabackup: This target seems to be already prepared.

Do you know about any further steps we can use to troubleshot what is the issue here?

Hi @Andrey_Sm . Let me jump-in this thread.

As mentioned by @matthewb in 8.0 we don’t halt the execution of prepare on the second time, rather we print a warning at the start of the log.

/work/pxb/ins/8.0/bin/xtrabackup --prepare --target-dir=/tmp/backup2 | grep prepare
xtrabackup: recognized server arguments: --innodb_checksum_algorithm=crc32 --innodb_log_checksums=1 --innodb_data_file_path=ibdata1:12M:autoextend --innodb_log_files_in_group=2 --innodb_log_file_size=1073741824 --innodb_page_size=16384 --innodb_undo_directory=./ --innodb_undo_tablespaces=2 --server-id=0 --innodb_log_checksums=ON --innodb_redo_log_encrypt=0 --innodb_undo_log_encrypt=0
xtrabackup: recognized client arguments: --prepare=1 --target-dir=/tmp/backup2
/work/pxb/ins/8.0/bin/xtrabackup version 8.0.22-15 based on MySQL server 8.0.22 Linux (x86_64) (revision id: 95683c0d6cd)
xtrabackup: cd to /tmp/backup2/
xtrabackup: This target seems to be already prepared.
Number of pools: 1
xtrabackup: notice: xtrabackup_logfile was already used to '--prepare'.

Instead of posting just a snippet of the log, can you please run --prepare twice and send us the full output of your terminal?

Also, can you please send us the output of cat /var/lib/backup/DB-name-backup/xtrabackup_checkpoints . This file should show backup_type = full-prepared after you ran prepare once.

Thanks

Here is the output of running prepare twice :

# xtrabackup  --prepare --target-dir=/var/lib/backup/db-name-backup
xtrabackup: recognized server arguments: --innodb_checksum_algorithm=crc32 --innodb_log_checksums=1 --innodb_data_file_path=ibdata1:12M:autoextend --innodb_log_files_in_group=2 --innodb_log_file_size=50331648 --innodb_page_size=16384 --innodb_undo_directory=./ --innodb_undo_tablespaces=2 --server-id=0 --innodb_log_checksums=ON --innodb_redo_log_encrypt=0 --innodb_undo_log_encrypt=0 
xtrabackup: recognized client arguments: --prepare=1 --target-dir=/var/lib/backup/db-name-backup 
xtrabackup version 8.0.22-15 based on MySQL server 8.0.22 Linux (x86_64) (revision id: fea8a0e)
xtrabackup: cd to /var/lib/backup/db-name-backup/
xtrabackup: This target seems to be already prepared.
Number of pools: 1
xtrabackup: notice: xtrabackup_logfile was already used to '--prepare'.
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 = 2
xtrabackup:   innodb_log_file_size = 50331648
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 = 2
xtrabackup:   innodb_log_file_size = 50331648
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
PUNCH HOLE support available
Mutexes and rw_locks use GCC atomic builtins
Uses event mutexes
GCC builtin __atomic_thread_fence() is used for memory barrier
Compressed tables use zlib 1.2.11
Number of pools: 1
Using CPU crc32 instructions
Directories to scan './'
Scanning './'
Completed space ID check of 4 files.
Initializing buffer pool, total size = 128.000000M, instances = 1, chunk size =128.000000M 
Completed initialization of buffer pool
page_cleaner coordinator priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
Starting to parse redo log at lsn = 62760568332, whereas checkpoint_lsn = 62760568332
Log background threads are being started...
Applying a batch of 0 redo log records ...
Apply batch completed!
Using undo tablespace './undo_001'.
Using undo tablespace './undo_002'.
Opened 2 existing undo tablespaces.
GTID recovery trx_no: 7733003
Removed temporary tablespace data file: "ibtmp1"
Creating shared tablespace for temporary tables
Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
File './ibtmp1' size is now 12 MB.
Scanning temp tablespace dir:'./#innodb_temp/'
Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
8.0.22 started; log sequence number 62760568332
Allocated tablespace ID 1 for sys/sys_config, old maximum was 0
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
FTS optimize thread exiting.
Starting shutdown...
Log background threads are being closed...
Shutdown completed; log sequence number 62760568332
Number of pools: 1
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 = 2
xtrabackup:   innodb_log_file_size = 50331648
PUNCH HOLE support available
Mutexes and rw_locks use GCC atomic builtins
Uses event mutexes
GCC builtin __atomic_thread_fence() is used for memory barrier
Compressed tables use zlib 1.2.11
Number of pools: 1
Using CPU crc32 instructions
Directories to scan './'
Scanning './'
Completed space ID check of 4 files.
Initializing buffer pool, total size = 128.000000M, instances = 1, chunk size =128.000000M 
Completed initialization of buffer pool
page_cleaner coordinator priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
Starting to parse redo log at lsn = 62760568332, whereas checkpoint_lsn = 62760568332
Log background threads are being started...
Applying a batch of 0 redo log records ...
Apply batch completed!
Using undo tablespace './undo_001'.
Using undo tablespace './undo_002'.
Opened 2 existing undo tablespaces.
GTID recovery trx_no: 7733003
Removed temporary tablespace data file: "ibtmp1"
Creating shared tablespace for temporary tables
Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
File './ibtmp1' size is now 12 MB.
Scanning temp tablespace dir:'./#innodb_temp/'
Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
8.0.22 started; log sequence number 62760568332
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
FTS optimize thread exiting.
Trying to access missing tablespace 4294967294
Starting shutdown...
Log background threads are being closed...
Shutdown completed; log sequence number 62760568332
210113 07:06:58 completed OK!
# xtrabackup  --prepare --target-dir=/var/lib/backup/db-name-backup
xtrabackup: recognized server arguments: --innodb_checksum_algorithm=crc32 --innodb_log_checksums=1 --innodb_data_file_path=ibdata1:12M:autoextend --innodb_log_files_in_group=2 --innodb_log_file_size=50331648 --innodb_page_size=16384 --innodb_undo_directory=./ --innodb_undo_tablespaces=2 --server-id=0 --innodb_log_checksums=ON --innodb_redo_log_encrypt=0 --innodb_undo_log_encrypt=0 
xtrabackup: recognized client arguments: --prepare=1 --target-dir=/var/lib/backup/db-name-backup 
xtrabackup version 8.0.22-15 based on MySQL server 8.0.22 Linux (x86_64) (revision id: fea8a0e)
xtrabackup: cd to /var/lib/backup/db-name-backup/
xtrabackup: This target seems to be already prepared.
Number of pools: 1
xtrabackup: notice: xtrabackup_logfile was already used to '--prepare'.
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 = 2
xtrabackup:   innodb_log_file_size = 50331648
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 = 2
xtrabackup:   innodb_log_file_size = 50331648
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
PUNCH HOLE support available
Mutexes and rw_locks use GCC atomic builtins
Uses event mutexes
GCC builtin __atomic_thread_fence() is used for memory barrier
Compressed tables use zlib 1.2.11
Number of pools: 1
Using CPU crc32 instructions
Directories to scan './'
Scanning './'
Completed space ID check of 4 files.
Initializing buffer pool, total size = 128.000000M, instances = 1, chunk size =128.000000M 
Completed initialization of buffer pool
page_cleaner coordinator priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
Starting to parse redo log at lsn = 62760568332, whereas checkpoint_lsn = 62760568332
Log background threads are being started...
Applying a batch of 0 redo log records ...
Apply batch completed!
Using undo tablespace './undo_001'.
Using undo tablespace './undo_002'.
Opened 2 existing undo tablespaces.
GTID recovery trx_no: 7733003
Removed temporary tablespace data file: "ibtmp1"
Creating shared tablespace for temporary tables
Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
File './ibtmp1' size is now 12 MB.
Scanning temp tablespace dir:'./#innodb_temp/'
Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
8.0.22 started; log sequence number 62760568332
Allocated tablespace ID 1 for sys/sys_config, old maximum was 0
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
FTS optimize thread exiting.
Starting shutdown...
Log background threads are being closed...
Shutdown completed; log sequence number 62760568332
Number of pools: 1
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 = 2
xtrabackup:   innodb_log_file_size = 50331648
PUNCH HOLE support available
Mutexes and rw_locks use GCC atomic builtins
Uses event mutexes
GCC builtin __atomic_thread_fence() is used for memory barrier
Compressed tables use zlib 1.2.11
Number of pools: 1
Using CPU crc32 instructions
Directories to scan './'
Scanning './'
Completed space ID check of 4 files.
Initializing buffer pool, total size = 128.000000M, instances = 1, chunk size =128.000000M 
Completed initialization of buffer pool
page_cleaner coordinator priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
page_cleaner worker priority: -20
Starting to parse redo log at lsn = 62760568332, whereas checkpoint_lsn = 62760568332
Log background threads are being started...
Applying a batch of 0 redo log records ...
Apply batch completed!
Using undo tablespace './undo_001'.
Using undo tablespace './undo_002'.
Opened 2 existing undo tablespaces.
GTID recovery trx_no: 7733003
Removed temporary tablespace data file: "ibtmp1"
Creating shared tablespace for temporary tables
Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
File './ibtmp1' size is now 12 MB.
Scanning temp tablespace dir:'./#innodb_temp/'
Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
8.0.22 started; log sequence number 62760568332
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
FTS optimize thread exiting.
Trying to access missing tablespace 4294967294
Starting shutdown...
Log background threads are being closed...
Shutdown completed; log sequence number 62760568332
210113 07:07:03 completed OK!
# 


This is checkpoint

cat /var/lib/backup/db-name-backup/xtrabackup_checkpoints   
backup_type = full-prepared
from_lsn = 0
to_lsn = 62760568197
last_lsn = 62760568207
flushed_lsn = 0

Hi @Andrey_Sm , your prepare stage is indeed showing the target is already prepared:

xtrabackup: This target seems to be already prepared.
and
xtrabackup: notice: xtrabackup_logfile was already used to '--prepare'.

@Marcelo_Altmann @matthewb

May be I didn’t understand the documentation properly…I thought it would be the only message about ,

xtrabackup: This target seems to be already prepared.

not this long output.

So everything is good in my case?

Everything looks good.

Thank you very much for your help guys.
Sorry for misunderstanding