Ambiguous docs/logging for --safe-slave-backup

[MikeG]

https://www.percona.com/doc/percona-xtrabackup/LATEST/innobackupex/replication_ibk.html

"""
 this option stops the slave SQL thread and wait to start backing up
"""

Testing (2.3.8) shows that the backup begins before replication is stopped - instead replication is stopped before issuing FTWRL (or backup/ddl/binlog locks)

Further, it does not seem to be logged when replication is stopped, only when started (without timestamp):

170726 20:42:10 Slave open temp tables: 0
170726 20:42:10 Slave is safe to backup
170726 20:42:10 Executing FLUSH NO_WRITE_TO_BINLOG TABLES...
170726 20:42:10 Executing FLUSH TABLES WITH READ LOCK...
170726 20:42:10 Starting to backup non-InnoDB tables and files

<SNIP>

170726 20:42:19 Executing UNLOCK TABLES
170726 20:42:19 All tables unlocked
Starting slave SQL thread

[MikeG (mikegriffin)]

Example desired logging output:

170726 20:42:10 Stopping slave SQL thread
170726 20:42:10 Slave open temp tables: 1
170726 20:42:10 Starting slave SQL thread
170726 20:42:10 Stopping slave SQL thread
170726 20:42:10 Slave open temp tables: 0
170726 20:42:10 Slave is safe to backup

<SNIP>

170726 20:42:18 [00] Streaming xtrabackup_slave_info
170726 20:42:18 Starting slave SQL thread

As far as docs, it would be nice if it was more clear that replication is not stopped for the duration of the backup (while streaming ibd files)

[Muhammad Irfan (muhammad-irfan)]

That's how the output likes:

170801 07:37:19 [01] Copying ./test_2/t.ibd to /home/mirfan/backups//2017-08-01_07-37-18/test_2/t.ibd
170801 07:37:19 [01] ...done
170801 07:37:20 >> log scanned up to (2544336)
170801 07:37:20 Slave open temp tables: 0
170801 07:37:20 Slave is safe to backup
170801 07:37:20 Executing LOCK TABLES FOR BACKUP...
170801 07:37:20 Starting to backup non-InnoDB tables and files
170801 07:37:20 [01] Copying ./test/t.frm to /home/mirfan/backups//2017-08-01_07-37-18/test/t.frm
170801 07:37:20 [01] ...done
.
.
170801 07:37:20 Finished backing up non-InnoDB tables and files
170801 07:37:20 Executing LOCK BINLOG FOR BACKUP...
170801 07:37:20 [00] Writing xtrabackup_slave_info
170801 07:37:20 [00] ...done
170801 07:37:20 [00] Writing xtrabackup_binlog_info
170801 07:37:20 [00] ...done
170801 07:37:20 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
xtrabackup: The latest check point (for incremental): '2540297'
xtrabackup: Stopping log copying thread.
.170801 07:37:20 >> log scanned up to (2544343)

170801 07:37:21 Executing UNLOCK BINLOG
170801 07:37:21 Executing UNLOCK TABLES
170801 07:37:21 All tables unlocked
Starting slave SQL thread
170801 07:37:21 Backup created in directory '/home/mirfan/backups//2017-08-01_07-37-18'

With that output, It seems that slave stopped message is there.

>> 170801 07:37:20 Slave open temp tables: 0
>> 170801 07:37:20 Slave is safe to backup

Resuming slave operation message is there too.

>> Starting slave SQL thread

To summarize, It seems like that messages are there but missing timestamp. Along with that, It's better to change wording in log to make it more clear.

[Sergei Glushchenko (sergei.glushchenko)]

We will change wording to make it more clear when slave thread has been stopped and add timestamps.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXB-1037