xtrabackup restore fails

[deepthi]

Overview of the Issue

Vttablet encounters error while restoring from an xtrabackup file from s3.

Reproduction Steps

The error is intermittent so this is not guaranteed to reproduce.
Take a backup using -backup_engine_implementation=xtrabackup and -backup_storage_implementation=s3
Try to bring up a replica using the backup (-restore_from_backup)

Binary version

Operating system and Environment details

OS, Architecture, and any other information you can provide
about the environment.

• Operating system (output of cat /etc/os-release):
• Kernel version (output of uname -sr):
• Architecture (output of uname -m):

Log Fragments

I0122 11:37:47.547542   12560 xtrabackupengine.go:644] xbstream stderr: mysql/time_zone_transition.ibd
I0122 11:37:47.656879   12560 xtrabackupengine.go:644] xbstream stderr: vt_keyspace_redacted/table_redacted.ibd
I0122 12:43:53.718097   12560 xtrabackupengine.go:644] xbstream stderr: xb_stream_read_chunk()d
I0122 11:37:47.546460   12560 xtrabackupengine.go:644] xbstream stderr: mysql/time_zone_name.i
bd
I0122 11:37:47.547542   12560 xtrabackupengine.go:644] xbstream stderr: mysql/time_zone_transi
tion.ibd
I0122 11:37:47.656879   12560 xtrabackupengine.go:644] xbstream stderr: vt_keyspace_redacted/table_redacted.ib
d
I0122 12:43:53.718097   12560 xtrabackupengine.go:644] xbstream stderr: xb_stream_read_chunk()
: my_read() failed.
E0122 12:43:53.720417   12560 xtrabackupengine.go:532] failed to close gzip decompressor: read tcp redacted->redacted:443: read: connection reset by peer
E0122 12:43:53.720445   12560 xtrabackupengine.go:414] error extracting backup files: exit status 1
xbstream failed
I0122 12:43:53.956702   12560 state_change.go:135] Executing post-action state refresh: failed for restore from backup
W0122 12:43:53.959519   12560 action_agent.go:773] Cannot get current mysql port, not checking it (will retry at healthcheck interval): net.Dial(/mnt/vitess/mysql/datadir/mysql.sock) to local server failed: dial unix /mnt/vitess/mysql/datadir/mysql.sock: connect: no such file or directory (errno 2002) (sqlstate HY000)
I0122 12:43:53.959562   12560 state_change.go:173] Running tablet callback because: failed for restore from backup
I0122 12:43:54.148804   12560 state_change.go:334] Disabling query service on type change, reason: after restore from backup
I0122 12:43:54.148829   12560 updatestreamctl.go:213] Enabling update stream, dbname: vt_keyspace_redacted
I0122 12:43:54.148867   12560 state_change.go:162] Done with post-action state refresh
I0122 12:43:54.148887   12560 shard_sync.go:73] Change to tablet state
F0122 12:43:54.148885   12560 action_agent.go:339] RestoreFromBackup failed: exit status 1
xbstream failed
Can't restore backup

[enisoc]

What is the size of the vt_keyspace_redacted/table_redacted.ibd file? How much of it was written to disk before xbstream died?

[deepthi]

longer stack trace:

I0124 09:37:53.511757   70097 backupengine.go:250] Restore: reinit config file
I0124 09:37:53.511763   70097 mysqld.go:894] Mysqld.ReinitConfig
I0124 09:37:53.511811   70097 mysqld.go:775] make_mycnf hook doesn't exist, reading template files
I0124 09:37:53.512184   70097 xtrabackupengine.go:385] Restore: Extracting files from backup.xbstream.gz
2020/01/24 09:37:53 DEBUG: Request s3/GetObject Details:
---[ REQUEST POST-SIGN ]-----------------------------
GET /<redacted>/backup.xbstream.gz HTTP/1.1
Host: <redacted>
User-Agent: aws-sdk-go/1.13.4 (go1.12.1; linux; amd64)
Authorization: <redacted> Credential=<redacted, SignedHeaders=<redacted>
X-Amz-Content-Sha256: <redacted>
X-Amz-Date: <redacted>
Accept-Encoding: gzip
\r
-----------------------------------------------------
2020/01/24 09:37:53 DEBUG: Response s3/GetObject Details:
---[ RESPONSE ]--------------------------------------
HTTP/1.1 200 OK
Content-Length: 639381289691
Accept-Ranges: bytes
Content-Type: binary/octet-stream
Date: Fri, 24 Jan 2020 17:37:54 GMT
Etag: "<redacted>"
Last-Modified: Wed, 22 Jan 2020 14:22:34 GMT
Server: AmazonS3
X-Amz-Expiration: expiry-date=<redacted>
X-Amz-Id-2: <redacted>
X-Amz-Replication-Status: COMPLETED
X-Amz-Request-Id: <redacted>
X-Amz-Server-Side-Encryption: AES256
\r
-----------------------------------------------------
I0124 09:37:53.635405   70097 xtrabackupengine.go:580] Executing xbstream cmd: xbstream [--parallel 4 -C /mnt/vitess/mysql/datadir/tmp/xtrabackup-2020-01-24.173753 -xv]
I0124 09:37:53.637661   70097 xtrabackupengine.go:644] xbstream stderr: encryption: using gcrypt 1.6.5
I0124 09:37:53.638113   70097 xtrabackupengine.go:644] xbstream stderr: mysql/innodb_table_stats.ibd
I0124 09:37:53.640009   70097 xtrabackupengine.go:644] xbstream stderr: sys/sys_config.ibd
I0124 09:37:53.640947   70097 xtrabackupengine.go:644] xbstream stderr: mysql/time_zone_leap_second.ibd
I0124 09:45:00.165185   70097 xtrabackupengine.go:644] xbstream stderr: xb_stream_read_chunk(): my_read() failed.
E0124 09:45:00.167154   70097 xtrabackupengine.go:532] failed to close gzip decompressor: read tcp <readcted-ip>-><readcted-ip>: read: connection reset by peer
E0124 09:45:00.167177   70097 xtrabackupengine.go:414] error extracting backup files: exit status 1
xbstream failed
I0124 09:45:00.214952   70097 state_change.go:135] Executing post-action state refresh: failed for restore from backup

[deepthi]

Several issues have been uncovered while investigating this:

• vttablet OOM if s3 debug mode is enabled (-s3_backup_log_level LogDebugWithRequestRetries). This has been fixed by upgrade aws-sdk-go to 1.28.8 #5777
• Restore failure could lead to tablet getting stuck in a loop ([vttablet] -init_populate_metadata and -restore_from_backup shouldn't be used together  #5780). This has been fixed by populate local_metadata after agent has been initialized #5783.
• There is no retry logic during restore. A transient failure during download of a large backup requires starting over. This will be an enhancement.