xtrabackup 2.4: xb_stream_read_chunk(): wrong chunk magic at offset 0x35630d1.

I pressed enter a bit too early.

But here is a longer example:

https://gist.github.com/kedazo/32189da227000dd00cadd28512cacde2

Also, to make things worse, this also happens during SST:

WSREP_SST: [INFO] Proceeding with SST (20161205 12:23:30.362)
WSREP_SST: [INFO] Evaluating socat -u TCP-LISTEN:4444,reuseaddr stdio | xbstream -x; RC=( ${PIPESTATUS[@]} ) (20161205 12:23:30.368)
WSREP_SST: [INFO] Cleaning the existing datadir and innodb-data/log directories (20161205 12:23:30.371)
WSREP_SST: [INFO] Waiting for SST streaming to complete! (20161205 12:23:30.425)
2016-12-05T12:23:31.117606Z 0 [Note] WSREP: (a04e0819, 'tcp://0.0.0.0:4567') turning message relay requesting off
xb_stream_read_chunk(): wrong chunk magic at offset 0x70bdc77.
2016-12-05T12:23:44.247957Z 0 [Note] WSREP: 1.0 (10.10.10.11): State transfer to 0.0 (10.10.10.12) complete.

Maybe there is a new setting that we have forgot to take into account.

[MYSQLD]
user=mysql
basedir=/usr/
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
pid-file=/var/lib/mysql/mysql.pid
port=3306
log_error=/var/log/mysql/mysqld.log
log_warnings=2
innodb_buffer_pool_size=185M
innodb_flush_log_at_trx_commit=2
innodb_file_per_table=1
innodb_data_file_path = ibdata1:100M:autoextend
innodb_read_io_threads=4
innodb_write_io_threads=4
innodb_doublewrite=1
innodb_log_file_size=64M
innodb_log_buffer_size=16M
innodb_buffer_pool_instances=-1
innodb_log_files_in_group=2
innodb_thread_concurrency=64
innodb_flush_method = O_DIRECT
innodb_autoinc_lock_mode=2
innodb_stats_on_metadata=0
default_storage_engine=innodb

# REPLICATION SPECIFIC
server_id=2
binlog_format=ROW

# OTHER THINGS, BUFFERS ETC
tmp_table_size = 64M
max_heap_table_size = 64M
max_allowed_packet = 512M

memlock=0
sysdate_is_now=1
max_connections=500
thread_cache_size=512
query_cache_type = 0
query_cache_size = 0
table_open_cache=1024
lower_case_table_names=0

performance_schema = 0
performance-schema-max-mutex-classes = 0
performance-schema-max-mutex-instances = 0

wsrep_provider=/usr/lib/libgalera_smm.so
wsrep_on=ON
wsrep_node_address=10.10.10.12

wsrep_provider_options="gcache.size=1024M; gmcast.segment=0"

wsrep_cluster_name="my_wsrep_cluster"

wsrep_cluster_address=gcomm://10.10.10.11:4567,10.10.10.12:4567,10.10.10.13:4567

wsrep_node_name=10.10.10.12

wsrep_slave_threads=4

wsrep_certify_nonPK=1

wsrep_max_ws_rows=131072

wsrep_max_ws_size=1073741824

wsrep_debug=0

wsrep_convert_LOCK_to_trx=0

wsrep_retry_autocommit=1

wsrep_auto_increment_control=1

wsrep_replicate_myisam=0

wsrep_drupal_282555_workaround=0

wsrep_causal_reads=0

wsrep_sst_method=xtrabackup-v2

wsrep_sst_auth=backupuser:password

[MYSQL]
socket=/var/lib/mysql/mysql.sock

[client]
socket=/var/lib/mysql/mysql.sock

[xtrabackup]
user=backupuser
password=password
ssl=0

It looks like something got into "backup.xbstream". Looking at the log, it may be at the end of the file. What is the size of "backup.xbstream" is it much larger than offset reported in the error message? Do you see something suspicious at the end of the "backup.xbstream"?

Hi,

Yes, the question is what :)

Here is:

root@n1:/home/vagrant# xbstream -x < /root/backup/backup.xbstream -C /tmp/restore/
xb_stream_read_chunk(): wrong chunk magic at offset 0xd8c0dd5.

root@n1:/home/vagrant# ls -al /root/backup/backup.xbstream
-rw-r--r-- 1 root root 227282483 Dec 5 13:27 /root/backup/backup.xbstream

offset translates to: 227282389

So it is as the end.

I can attached the backup.xbstream file here if you want or else let me know if there is anything you want me to run.

BR
johan

Probably something like will tell us more:

xxd /root/backup/backup.xbstream | tail -n 100

Okay, it seems the problem is that we had

[xtrabackup]
ssl=0

and

 tail -n5 backup.xbstream
format = xbstream
compact = N
compressed = N
encrypted = N
XBSTCK01Extrabackup_infoWARNING: --ssl is deprecated and will be removed in a future version. Use --ssl-mode instead.

So changing then to use:

ssl_mode=DISABLED

seems to resolve this.

Hopefully this helps some one else too with problems in this area.

BR
johan

Hi,

I have similar issue and in my case xbstream has the following lines at the end:

# tail -n5 /home/kedz/backups/BACKUP-5/backup-full-2016-12-05_143905.xbstream
format = xbstream
compact = N
compressed = N
encrypted = N
XBSTCK01Extrabackup_infoWARNING: --ssl is deprecated and will be removed in a future version. Use --ssl-mode instead.

Could this be the root cause?

Yes. We need to make sure this warning is written into stderr instead of stdout.

https://github.com/percona/percona-xtrabackup/pull/302

Hi there, we have been using ssl_mode=DISABLED in [xtrabackup] but now a new strange message has appeared at the end of xtrabackups (and causing invalid chunk errors on joiner side):

root@ubuntu-xenial:~# tail -1 data.out
XBSTCK01Extrabackup_infoWARNING: no verification of server certificate will be done. Use --ssl-mode=VERIFY_CA or VERIFY_IDENTITY.

It is with a Percona 5.7 Galera cluster, with the following xtrabackup version:
root@ubuntu-xenial:~# xtrabackup --version
xtrabackup version 2.4.5 based on MySQL server 5.7.13 Linux (x86_64) (revision id: e41c0be)

Could you please make/fix xtrabackup to not to print WARNING messages into the stream?

Hi there, I've created a pull request to hot-fix this printing into the backup stream issue:
-> https://github.com/percona/percona-xtrabackup/pull/305

Br, David

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