MySQL backups fail when backup creation fails

Products

• VMware Tanzu SQL

Issue/Introduction

This article discusses how to determine what to do when a MySQL backup fails while creating the backup file.

A successful MySQL backup for a service instance involves the creation of the backup, then the backup is moved to the desired destination. 

When the backup can't be created, a message similar to the following will be logged:

{"timestamp":"1558038454.729307413","source":"ServiceBackup","message":"ServiceBackup.WithIdentifier.Perform backup completed with error","log_level":2,"data":{"backup_guid":"023b4882-0971-45e0-bc5c-cdc159f25c9b","error":"exit status 2","identifier":"service-instance_569cca63-d00a-46ce-afc2-f4bd17427549","session":"1"}}
{"timestamp":"1558038454.729371309","source":"ServiceBackup","message":"ServiceBackup.Error running backup","log_level":2,"data":{"error":"exit status 2"}}

However, it can be difficult to determine the cause for the failure from messages like these.

Resolution

When there is an error creating the backup, determining the cause of the failure can be difficult. The details in the /var/vcap/sys/log/service-backup/out.log are vague and the manual-backup tool doesn't log many details.

Alternatively, you should look in the /var/vcap/data/sys/log/streaming-mysql-backup-client/streaming-mysql-backup-client.stderr.log. There may be entries in this log similar to the following:

{"timestamp":"1558038454.455193520","source":"/var/vcap/packages/streaming-mysql-backup-client/bin/streaming-mysql-backup-client","message":"/var/vcap/packages/streaming-mysql-backup-client/bin/streaming-mysql-backup-client.Preparing the backup failed","log_level":2,"data":{"error":"exit status 1","ip":"q-m547n2s0.q-g314.bosh","output":"L3Zhci92Y2FwL3BhY2thZ2VzL3h0cmFiYWNrdXAvYmluL3h0cmFiYWNrdXAgdmVyc2lvbiAyLjQuOCBiYXNlZCBvbiBNeVNRTCBzZXJ2ZXIgNS43LjEzIExpbnV4ICh4ODZfNjQpIChyZXZpc2lvbiBpZDogOTczMzBmNykKeHRyYWJhY2t1cDogY2QgdG8gL3Zhci92Y2FwL3N0b3JlL215c3FsLWJhY2t1cHMtdG1wL215c3FsLWJhY2t1cC1wcmVwYXJlNTgzNDQ2ODg1Lwp4dHJhYmFja3VwOiBUaGlzIHRhcmdldCBzZWVtcyB0byBiZSBub3QgcHJlcGFyZWQgeWV0LgpJbm5vREI6IE51bWJlciBvZiBwb29sczogMQp4dHJhYmFja3VwOiB4dHJhYmFja3VwX2xvZ2ZpbGUgZGV0ZWN0ZWQ6IHNpemU9ODM4ODYwOCwgc3RhcnRfbHNuPSgyNjAxMDY4KQp4dHJhYmFja3VwOiB1c2luZyB0aGUgZm9sbG93aW5nIElubm9EQiBjb25maWd1cmF0aW9uIGZvciByZWNvdmVyeToKeHRyYWJhY2t1cDogICBpbm5vZGJfZGF0YV9ob21lX2RpciA9IC4KeHRyYWJhY2t1cDogICBpbm5vZGJfZGF0YV9maWxlX3BhdGggPSBpYmRhdGExOjEyTTphdXRvZXh0ZW5kCnh0cmFiYWNrdXA6ICAgaW5ub2RiX2xvZ19ncm91cF9ob21lX2RpciA9IC4KeHRyYWJhY2t1cDogICBpbm5vZGJfbG9nX2ZpbGVzX2luX2dyb3VwID0gMQp4dHJhYmFja3VwOiAgIGlubm9kYl9sb2dfZmlsZV9zaXplID0gODM4ODYwOAp4dHJhYmFja3VwOiB1c2luZyB0aGUgZm9sbG93aW5nIElubm9EQiBjb25maWd1cmF0aW9uIGZvciByZWNvdmVyeToKeHRyYWJhY2t1cDogICBpbm5vZGJfZGF0YV9ob21lX2RpciA9IC4KeHRyYWJhY2t1cDogICBpbm5vZGJfZGF0YV9maWxlX3BhdGggPSBpYmRhdGExOjEyTTphdXRvZXh0ZW5kCnh0cmFiYWNrdXA6ICAgaW5ub2RiX2xvZ19ncm91cF9ob21lX2RpciA9IC4KeHRyYWJhY2t1cDogICBpbm5vZGJfbG9nX2ZpbGVzX2luX2dyb3VwID0gMQp4dHJhYmFja3VwOiAgIGlubm9kYl9sb2dfZmlsZV9zaXplID0gODM4ODYwOAp4dHJhYmFja3VwOiBTdGFydGluZyBJbm5vREIgaW5zdGFuY2UgZm9yIHJlY292ZXJ5Lgp4dHJhYmFja3VwOiBVc2luZyAxMDQ4NTc2MDAgYnl0ZXMgZm9yIGJ1ZmZlciBwb29sIChzZXQgYnkgLS11c2UtbWVtb3J5IHBhcmFtZXRlcikKSW5ub0RCOiBQVU5DSCBIT0xFIHN1cHBvcnQgYXZhaWxhYmxlCklubm9EQjogTXV0ZXhlcyBhbmQgcndfbG9ja3MgdXNlIEdDQyBhdG9taWMgYnVpbHRpbnMKSW5ub0RCOiBVc2VzIGV2ZW50IG11dGV4ZXMKSW5ub0RCOiBHQ0MgYnVpbHRpbiBfX2F0b21pY190aHJlYWRfZmVuY2UoKSBpcyB1c2VkIGZvciBtZW1vcnkgYmFycmllcgpJbm5vREI6IENvbXByZXNzZWQgdGFibGVzIHVzZSB6bGliIDEuMi44Cklubm9EQjogTnVtYmVyIG9mIHBvb2xzOiAxCklubm9EQjogVXNpbmcgQ1BVIGNyYzMyIGluc3RydWN0aW9ucwpJbm5vREI6IEluaXRpYWxpemluZyBidWZmZXIgcG9vbCwgdG90YWwgc2l6ZSA9IDEwME0sIGluc3RhbmNlcyA9IDEsIGNodW5rIHNpemUgPSAxMDBNCklubm9EQjogQ29tcGxldGVkIGluaXRpYWxpemF0aW9uIG9mIGJ1ZmZlciBwb29sCklubm9EQjogcGFnZV9jbGVhbmVyIGNvb3JkaW5hdG9yIHByaW9yaXR5OiAtMjAKSW5ub0RCOiBIaWdoZXN0IHN1cHBvcnRlZCBmaWxlIGZvcm1hdCBpcyBCYXJyYWN1ZGEuCklubm9EQjogTG9nIHNjYW4gcHJvZ3Jlc3NlZCBwYXN0IHRoZSBjaGVja3BvaW50IGxzbiAyNjAxMDY4Cklubm9EQjogRG9pbmcgcmVjb3Zlcnk6IHNjYW5uZWQgdXAgdG8gbG9nIHNlcXVlbmNlIG51bWJlciAyNjAxMTE5ICgwJSkKSW5ub0RCOiBEb2luZyByZWNvdmVyeTogc2Nhbm5lZCB1cCB0byBsb2cgc2VxdWVuY2UgbnVtYmVyIDI2MDExMTkgKDAlKQpJbm5vREI6IERhdGFiYXNlIHdhcyBub3Qgc2h1dGRvd24gbm9ybWFsbHkhCklubm9EQjogU3RhcnRpbmcgY3Jhc2ggcmVjb3ZlcnkuCklubm9EQjogeHRyYWJhY2t1cDogTGFzdCBNeVNRTCBiaW5sb2cgZmlsZSBwb3NpdGlvbiAxNTQsIGZpbGUgbmFtZSBteXNxbC1iaW4uMDAwMDAyCklubm9EQjogQ3JlYXRpbmcgc2hhcmVkIHRhYmxlc3BhY2UgZm9yIHRlbXBvcmFyeSB0YWJsZXMKSW5ub0RCOiBTZXR0aW5nIGZpbGUgJy4vaWJ0bXAxJyBzaXplIHRvIDEyIE1CLiBQaHlzaWNhbGx5IHdyaXRpbmcgdGhlIGZpbGUgZnVsbDsgUGxlYXNlIHdhaXQgLi4uCklubm9EQjogRmlsZSAnLi9pYnRtcDEnIHNpemUgaXMgbm93IDEyIE1CLgpJbm5vREI6IDk2IHJlZG8gcm9sbGJhY2sgc2VnbWVudChzKSBmb3VuZC4gMSByZWRvIHJvbGxiYWNrIHNlZ21lbnQocykgYXJlIGFjdGl2ZS4KSW5ub0RCOiAzMiBub24tcmVkbyByb2xsYmFjayBzZWdtZW50KHMpIGFyZSBhY3RpdmUuCklubm9EQjogV2FpdGluZyBmb3IgcHVyZ2UgdG8gc3RhcnQKSW5ub0RCOiA1LjcuMTMgc3RhcnRlZDsgbG9nIHNlcXVlbmNlIG51bWJlciAyNjAxMTE5Cklubm9EQjogeHRyYWJhY2t1cDogTGFzdCBNeVNRTCBiaW5sb2cgZmlsZSBwb3NpdGlvbiAxNTQsIGZpbGUgbmFtZSBteXNxbC1iaW4uMDAwMDAyCgp4dHJhYmFja3VwOiBzdGFydGluZyBzaHV0ZG93biB3aXRoIGlubm9kYl9mYXN0X3NodXRkb3duID0gMQpJbm5vREI6IEZUUyBvcHRpbWl6ZSB0aHJlYWQgZXhpdGluZy4KSW5ub0RCOiBTdGFydGluZyBzaHV0ZG93bi4uLgpJbm5vREI6IFNodXRkb3duIGNvbXBsZXRlZDsgbG9nIHNlcXVlbmNlIG51bWJlciAyNjAxMTM4Cklubm9EQjogTnVtYmVyIG9mIHBvb2xzOiAxCnh0cmFiYWNrdXA6IHVzaW5nIHRoZSBmb2xsb3dpbmcgSW5ub0RCIGNvbmZpZ3VyYXRpb24gZm9yIHJlY292ZXJ5Ogp4dHJhYmFja3VwOiAgIGlubm9kYl9kYXRhX2hvbWVfZGlyID0gLgp4dHJhYmFja3VwOiAgIGlubm9kYl9kYXRhX2ZpbGVfcGF0aCA9IGliZGF0YTE6MTJNOmF1dG9leHRlbmQKeHRyYWJhY2t1cDogICBpbm5vZGJfbG9nX2dyb3VwX2hvbWVfZGlyID0gLgp4dHJhYmFja3VwOiAgIGlubm9kYl9sb2dfZmlsZXNfaW5fZ3JvdXAgPSAyCnh0cmFiYWNrdXA6ICAgaW5ub2RiX2xvZ19maWxlX3NpemUgPSAyNjg0MzU0NTYKSW5ub0RCOiBQVU5DSCBIT0xFIHN1cHBvcnQgYXZhaWxhYmxlCklubm9EQjogTXV0ZXhlcyBhbmQgcndfbG9ja3MgdXNlIEdDQyBhdG9taWMgYnVpbHRpbnMKSW5ub0RCOiBVc2VzIGV2ZW50IG11dGV4ZXMKSW5ub0RCOiBHQ0MgYnVpbHRpbiBfX2F0b21pY190aHJlYWRfZmVuY2UoKSBpcyB1c2VkIGZvciBtZW1vcnkgYmFycmllcgpJbm5vREI6IENvbXByZXNzZWQgdGFibGVzIHVzZSB6bGliIDEuMi44Cklubm9EQjogTnVtYmVyIG9mIHBvb2xzOiAxCklubm9EQjogVXNpbmcgQ1BVIGNyYzMyIGluc3RydWN0aW9ucwpJbm5vREI6IEluaXRpYWxpemluZyBidWZmZXIgcG9vbCwgdG90YWwgc2l6ZSA9IDEwME0sIGluc3RhbmNlcyA9IDEsIGNodW5rIHNpemUgPSAxMDBNCklubm9EQjogQ29tcGxldGVkIGluaXRpYWxpemF0aW9uIG9mIGJ1ZmZlciBwb29sCklubm9EQjogcGFnZV9jbGVhbmVyIGNvb3JkaW5hdG9yIHByaW9yaXR5OiAtMjAKSW5ub0RCOiBTZXR0aW5nIGxvZyBmaWxlIC4vaWJfbG9nZmlsZTEwMSBzaXplIHRvIDI1NiBNQgpJbm5vREI6IFByb2dyZXNzIGluIE1COgogMTAwIDIwMApJbm5vREI6IFNldHRpbmcgbG9nIGZpbGUgLi9pYl9sb2dmaWxlMSBzaXplIHRvIDI1NiBNQgpJbm5vREI6IFByb2dyZXNzIGluIE1COgogMTAwSW5ub0RCOiAxMDQ4NTc2IGJ5dGVzIHNob3VsZCBoYXZlIGJlZW4gd3JpdHRlbi4gT25seSA5NjI1NjAgYnl0ZXMgd3JpdHRlbi4gUmV0cnlpbmcgZm9yIHRoZSByZW1haW5pbmcgYnl0ZXMuCklubm9EQjogUmV0cnkgYXR0ZW1wdHMgZm9yIHdyaXRpbmcgcGFydGlhbCBkYXRhIGZhaWxlZC4KSW5ub0RCOiBXcml0ZSB0byBmaWxlIC4vaWJfbG9nZmlsZTFmYWlsZWQgYXQgb2Zmc2V0IDEyMjY4MzM5MiwgMTA0ODU3NiBieXRlcyBzaG91bGQgaGF2ZSBiZWVuIHdyaXR0ZW4sIG9ubHkgOTYyNTYwIHdlcmUgd3JpdHRlbi4gT3BlcmF0aW5nIHN5c3RlbSBlcnJvciBudW1iZXIgMjguIENoZWNrIHRoYXQgeW91ciBPUyBhbmQgZmlsZSBzeXN0ZW0gc3VwcG9ydCBmaWxlcyBvZiB0aGlzIHNpemUuIENoZWNrIGFsc28gdGhhdCB0aGUgZGlzayBpcyBub3QgZnVsbCBvciBhIGRpc2sgcXVvdGEgZXhjZWVkZWQuCklubm9EQjogRXJyb3IgbnVtYmVyIDI4IG1lYW5zICdObyBzcGFjZSBsZWZ0IG9uIGRldmljZScKSW5ub0RCOiBTb21lIG9wZXJhdGluZyBzeXN0ZW0gZXJyb3IgbnVtYmVycyBhcmUgZGVzY3JpYmVkIGF0IGh0dHA6Ly9kZXYubXlzcWwuY29tL2RvYy9yZWZtYW4vNS43L2VuL29wZXJhdGluZy1zeXN0ZW0tZXJyb3ItY29kZXMuaHRtbApJbm5vREI6IENhbm5vdCBzZXQgbG9nIGZpbGUgLi9pYl9sb2dmaWxlMSB0byBzaXplIDI1NiBNQgpJbm5vREI6IFBsdWdpbiBpbml0aWFsaXphdGlvbiBhYm9ydGVkIHdpdGggZXJyb3IgR2VuZXJpYyBlcnJvcgp4dHJhYmFja3VwOiBpbm5vZGJfaW5pdCgpOiBFcnJvciBvY2N1cmVkLgo="}}
{"timestamp":"1558038454.724997997","source":"/var/vcap/packages/streaming-mysql-backup-client/bin/streaming-mysql-backup-client","message":"/var/vcap/packages/streaming-mysql-backup-client/bin/streaming-mysql-backup-client.All backups failed. Not able to generate a valid backup artifact. See error(s) below: %s","log_level":3,"data":{"error":"\nexit status 1","trace":"goroutine 1 [running]:\nstreaming-mysql-backup-client/vendor/code.cloudfoundry.org/lager.(*logger).Fatal(0xc420056360, 0x747982, 0x58, 0x8abb80, 0xc420130440, 0x0, 0x0, 0x0)\n\t/var/vcap/packages/streaming-mysql-backup-client/src/streaming-mysql-backup-client/vendor/code.cloudfoundry.org/lager/logger.go:132 +0xca\nmain.main()\n\t/var/vcap/packages/streaming-mysql-backup-client/src/streaming-mysql-backup-client/main.go:21 +0x12c\n"}}

There are two log entries in the snippet above, each beginning with `{"timestamp"`.

While the second entry, "Not able to generate a valid backup artifact", appears interesting, it is really the first entry that is most interesting!

In the first entry, everything between `"output":"` and `"}}` is a base64 encoded message. This is the long string beginning with "L3Zhc" and ending with "kLgo=".

Decoding this base64 string reveals the true issue. There are many ways to decode base64. One way is to install "jq" on the MySQL VM, then examining the log with the following commands:

# jq -r 'select(.data.output != null) | .data.output' /var/vcap/data/sys/log/streaming-mysql-backup-client/streaming-mysql-backup-client.stderr.log | base64 -d
/var/vcap/packages/xtrabackup/bin/xtrabackup version 2.4.8 based on MySQL server 5.7.13 Linux (x86_64) (revision id: 97330f7)
xtrabackup: cd to /var/vcap/store/mysql-backups-tmp/mysql-backup-prepare003968311/
xtrabackup: This target seems to be not prepared yet.
InnoDB: Number of pools: 1
xtrabackup: xtrabackup_logfile detected: size=8388608, start_lsn=(2601068)
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 = 1
xtrabackup:   innodb_log_file_size = 8388608
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 = 1
xtrabackup:   innodb_log_file_size = 8388608
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: PUNCH HOLE support available
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Uses event mutexes
InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
InnoDB: Compressed tables use zlib 1.2.8
InnoDB: Number of pools: 1
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M
InnoDB: Completed initialization of buffer pool
InnoDB: page_cleaner coordinator priority: -20
InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 2601068
InnoDB: Doing recovery: scanned up to log sequence number 2601119 (0%)
InnoDB: Doing recovery: scanned up to log sequence number 2601119 (0%)
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.
InnoDB: xtrabackup: Last MySQL binlog file position 154, file name mysql-bin.000002
InnoDB: Creating shared tablespace for temporary tables
InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
InnoDB: File './ibtmp1' size is now 12 MB.
InnoDB: 96 redo rollback segment(s) found. 1 redo rollback segment(s) are active.
InnoDB: 32 non-redo rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.7.13 started; log sequence number 2601119
InnoDB: xtrabackup: Last MySQL binlog file position 154, file name mysql-bin.000002

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
InnoDB: Shutdown completed; log sequence number 2601138
InnoDB: 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 = 268435456
InnoDB: PUNCH HOLE support available
InnoDB: Mutexes and rw_locks use GCparse error: Invalid numeric literal at line 3, column 6
C atomic builtins
InnoDB: Uses event mutexes
InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
InnoDB: Compressed tables use zlib 1.2.8
InnoDB: Number of pools: 1
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M
InnoDB: Completed initialization of buffer pool
InnoDB: page_cleaner coordinator priority: -20
InnoDB: Setting log file ./ib_logfile101 size to 256 MB
InnoDB: Progress in MB:
 100 200
InnoDB: Setting log file ./ib_logfile1 size to 256 MB
InnoDB: Progress in MB:
 100InnoDB: 1048576 bytes should have been written. Only 962560 bytes written. Retrying for the remaining bytes.
InnoDB: Retry attempts for writing partial data failed.
InnoDB: Write to file ./ib_logfile1failed at offset 122683392, 1048576 bytes should have been written, only 962560 were written. Operating system error number 28. Check that your OS and file system support files of this size. Check also that the disk is not full or a disk quota exceeded.
InnoDB: Error number 28 means 'No space left on device'
InnoDB: Some operating system error numbers are described at http://dev.mysql.com/doc/refman/5.7/en/operating-system-error-codes.html
InnoDB: Cannot set log file ./ib_logfile1 to size 256 MB
InnoDB: Plugin initialization aborted with error Generic error
xtrabackup: innodb_init(): Error occured.

In this case, the persistent disk is too small to create the backup, as indicated by the message "No space left on device".