Re: VCSA 6.7 Native Backup Fails with Timeout - 72...

MSchaff · ‎09-04-2019

Hello,

I have an automatic backup scheduled of a vCenter appliance (version 6.7.0.21000). I'm using the FTPS protocol. The backups seem to start fine and run for about seven or eight minutes, transferring roughly 3 GB of data to the FTP server, but something must be happening at that point, because the automated job goes in to a holding pattern, and times out twenty hours later. The message in the backup log is:

Timeout! Failed to complete in 72000 seconds.

There is no other indicator of what exactly caused the timeout. I can see the files on the FTP server, so it doesn't appear to be a permissions issue.

The error occurs each time the scheduled job runs (weekly). I'm wondering if anyone has experienced this, and has a possible suggestion on how to resolve it. Below is the most recent error text from the backup log. Thanks in advance for any assistance with this!

2019-09-02T04:59:14.303 [MainProcess:PID-45427] INFO: The location provided: ftp://10.1.250.249/VCenter_Server_Backups/vCenter/sn_dcnvcsvr.dcn-nd.com/S_6.7.0.21000_20190902-0459...

2019-09-02T04:59:14.340 [MainProcess:PID-45427] INFO: Starting backup job...

2019-09-02T04:59:14.616 [MainProcess:PID-45427] INFO: Estimating full VCDB size.

2019-09-02T04:59:14.616 [MainProcess:PID-45427] INFO: Estimating /storage/db/vpostgres compressed size.

2019-09-02T04:59:14.656 [MainProcess:PID-45427] INFO: original size: 673987241, compressed size: 121385102.1041, compression ratio: 0.1801

2019-09-02T04:59:14.656 [MainProcess:PID-45427] INFO: Estimating /storage/seat/vpostgres compressed size.

2019-09-02T04:59:14.719 [MainProcess:PID-45427] INFO: original size: 2922135552, compressed size: 420787519.488, compression ratio: 0.144

2019-09-02T04:59:14.719 [MainProcess:PID-45427] INFO: Estimating /root/.pgpass compressed size.

2019-09-02T04:59:14.719 [MainProcess:PID-45427] INFO: original size: 0, compressed size: 0.0, compression ratio: 0.1055

2019-09-02T04:59:14.719 [MainProcess:PID-45427] INFO: Estimating /var/log/vmware/vpostgres compressed size.

2019-09-02T04:59:14.720 [MainProcess:PID-45427] INFO: original size: 30756678, compressed size: 3244829.529, compression ratio: 0.1055

2019-09-02T04:59:14.720 [MainProcess:PID-45427] INFO: Estimating /etc/vmware/vm-support/vpostgres-support-noarch.mfx compressed size.

2019-09-02T04:59:14.720 [MainProcess:PID-45427] INFO: original size: 0, compressed size: 0.0, compression ratio: 0.1055

2019-09-02T04:59:14.720 [MainProcess:PID-45427] INFO: Estimating /storage/db/vpostgres_ssl compressed size.

2019-09-02T04:59:14.721 [MainProcess:PID-45427] INFO: original size: 15107, compressed size: 1593.7884999999999, compression ratio: 0.1055

2019-09-02T04:59:14.721 [MainProcess:PID-45427] INFO: Estimating /storage/dblog/vpostgres/pg_xlog compressed size.

2019-09-02T04:59:14.721 [MainProcess:PID-45427] INFO: original size: 436207616, compressed size: 99847923.3024, compression ratio: 0.2289

2019-09-02T04:59:14.721 [MainProcess:PID-45427] INFO: Estimated size:

original_size=4063102194,

compressed_size=645266968.212,

encrypted_size=709793665.0332

2019-09-02T04:59:14.721 [MainProcess:PID-45427] INFO: Calculate size for components

2019-09-02T04:59:14.942 [MainProcess:PID-45427] INFO: Archive size for component vum: 2560294666

2019-09-02T04:59:15.236 [MainProcess:PID-45427] INFO: Archive size for component rbd: 141405104

2019-09-02T04:59:15.807 [MainProcess:PID-45427] INFO: Archive size for component imagebuilder: 9175

2019-09-02T04:59:15.808 [MainProcess:PID-45427] INFO: Appliance Stats Monitor database file path: /var/vmware/applmgmt/appliance_stats.sqlite

2019-09-02T04:59:52.477 [MainProcess:PID-45427] INFO: The backup dir does not exist

2019-09-02T04:59:52.705 [MainProcess:PID-45427] INFO: Started to backup VC components at UTC: 2019-09-02 04:59:52.705612

2019-09-02T04:59:52.726 [LotusBackup:PID-45645] INFO: Starting backup Lotus.

2019-09-02T04:59:52.726 [LotusBackup:PID-45645] INFO: BackupLotus: Running /usr/lib/vmware-vmdir/bin/vdcbackup /storage/db/vmware-vmdir/ /tmp/backup_lotus/

2019-09-02T04:59:52.728 [ConfigFilesBackup:PID-45646] INFO: Started with configuration files backup.

2019-09-02T04:59:52.731 [VCDBBackup:PID-45647] INFO: Retrieving postgres server listening port

2019-09-02T04:59:52.732 [VCDBBackup:PID-45647] INFO: Executing command: netstat -plnt.

2019-09-02T04:59:52.738 [StatsMonitorDBBackup:PID-45649] INFO: Starting backup appliance monitor SQLite DB.

2019-09-02T04:59:52.739 [StatsMonitorDBBackup:PID-45649] INFO: Appliance Stats Monitor database file path: /var/vmware/applmgmt/appliance_stats.sqlite

2019-09-02T04:59:52.739 [StatsMonitorDBBackup:PID-45649] INFO: Executing command sqlite3 /var/vmware/applmgmt/appliance_stats.sqlite .dump.

2019-09-02T04:59:52.740 [ComponentScriptsBackup:PID-45648] INFO: Starting backup component: vum

2019-09-02T04:59:52.740 [ComponentScriptsBackup:PID-45648] INFO: Execute vum script: /etc/vmware/backup/component-scripts/vum/backup_restore.py --startBackup

2019-09-02T04:59:52.748 [ComponentScriptsBackup:PID-45648] INFO: Dispatching stream.

2019-09-02T04:59:52.801 [VCDBBackup:PID-45647] INFO: Starting VCDB full database backup

2019-09-02T04:59:52.801 [VCDBBackup:PID-45647] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', "select pg_xlogfile_name(pg_start_backup('backup_20190902_045913_11726888'));"].

2019-09-02T04:59:52.865 [ConfigFilesBackup:PID-45646] INFO: incl: /var/log/vmware/applmgmt/cfg_incl_l9z9zvsi.lst excl: /var/log/vmware/applmgmt/cfg_excl_5mm952rc.lst

2019-09-02T04:59:52.865 [ConfigFilesBackup:PID-45646] INFO: tarCmd = ['/usr/bin/tar', '-cz', '-C', '/', '--ignore-failed-read', '-T', '/var/log/vmware/applmgmt/cfg_incl_l9z9zvsi.lst', '-X', '/var/log/vmware/applmgmt/cfg_excl_5mm952rc.lst', '--warning', 'no-file-ignored']

2019-09-02T04:59:53.888 [LotusBackup:PID-45645] INFO: stdout: VdcBackupDB: Setting vmdir state to VMDIRD_READ_ONLY

VdcBackupDB: Backing up: /storage/db/vmware-vmdir//data.mdb

VdcBackupDB: Backing up: /storage/db/vmware-vmdir//lock.mdb

VdcBackupDB: Setting vmdir state to (3)

2019-09-02T04:59:53.889 [LotusBackup:PID-45645] INFO: BackupLotus: Dispatching files ['lock.mdb', 'data.mdb']

2019-09-02T04:59:53.889 [LotusBackup:PID-45645] INFO: tarCmd = ['/usr/bin/tar', '-cz', '-C', '/tmp/backup_lotus/', '--ignore-failed-read', '--warning', 'no-file-ignored', 'lock.mdb', 'data.mdb']

2019-09-02T04:59:59.597 [LotusBackup:PID-45645] INFO: Lotus backup finished successfully.

2019-09-02T04:59:59.606 [LotusBackup:PID-45645] INFO: Successfully completed Lotus cleanup.

2019-09-02T05:00:26.734 [ConfigFilesBackup:PID-45646] ERROR: rc: 0, stderr: /usr/bin/tar: etc/krb5.lotus.conf: Warning: Cannot stat: No such file or directory

/usr/bin/tar: etc/vmware-vcha/vmware-vmon.service.bak: Warning: Cannot stat: No such file or directory

/usr/bin/tar: etc/vmware-vsm/logging.properties: Warning: Cannot stat: No such file or directory

/usr/bin/tar: etc/vmware-vsm/wrapper/wrapper.conf: Warning: Cannot stat: No such file or directory

/usr/bin/tar: etc/vmware/appliance/firewall.conf: Warning: Cannot stat: No such file or directory

/usr/bin/tar: etc/vmware/appliance/firewall/ccm-firewall.conf: Warning: Cannot stat: No such file or directory

/usr/bin/tar: usr/lib/vmware-cm/wrapper/conf/wrapper.conf: Warning: Cannot stat: No such file or directory

/usr/bin/tar: usr/lib/vmware-vcha/data/pg-firewall-block.conf: Warning: Cannot stat: No such file or directory

/usr/bin/tar: usr/lib/vmware-vcha/data/pg_hba_block.conf: Warning: Cannot stat: No such file or directory

2019-09-02T05:00:26.735 [ConfigFilesBackup:PID-45646] INFO: Successfully finished configuration files backup.

2019-09-02T05:00:27.350 [StatsMonitorDBBackup:PID-45649] INFO: Completed backup appliance stats monitor SQLite DB.

2019-09-02T05:02:02.759 [ComponentScriptsBackup:PID-45648] INFO: Component vum backup successful.

2019-09-02T05:02:02.763 [ComponentScriptsBackup:PID-45648] INFO: Starting backup component: rbd

2019-09-02T05:02:02.763 [ComponentScriptsBackup:PID-45648] INFO: Execute rbd script: /etc/vmware/backup/component-scripts/rbd/rbd-backup-restore --startBackup

2019-09-02T05:02:02.773 [ComponentScriptsBackup:PID-45648] INFO: Dispatching stream.

2019-09-02T05:05:40.272 [VCDBBackup:PID-45647] INFO: Successfully start Postgres on-line backup window.

2019-09-02T05:05:40.273 [VCDBBackup:PID-45647] INFO: Backup start WAL file is 00000001000000630000002B.

2019-09-02T05:05:40.282 [VCDBBackup:PID-45647] INFO: tarCmd = ['/usr/bin/tar', '-cz', '-C', '/', '--ignore-failed-read', '--warning', 'no-file-ignored', '--warning', 'no-file-changed', '--warning', 'no-file-removed', 'storage/db/vpostgres', 'storage/seat/vpostgres', 'root/.pgpass', 'var/log/vmware/vpostgres', 'etc/vmware/vm-support/vpostgres-support-noarch.mfx', 'storage/db/vpostgres_ssl']

2019-09-02T05:05:40.283 [VCDB-WAL-Backup:PID-47925] INFO: Starting backup WAL files.

2019-09-02T05:05:40.284 [VCDB-WAL-Backup:PID-47925] INFO: VCDB backup start at WAL file 00000001000000630000002B.

2019-09-02T05:05:40.284 [VCDB-WAL-Backup:PID-47925] INFO: Each WAL backup image contains 5 WAL files.

2019-09-02T05:05:41.286 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:42.315 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:43.348 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:44.385 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:45.419 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:46.455 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:47.488 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:48.552 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:49.580 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:50.619 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:51.658 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:52.684 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:53.708 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:54.732 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:55.751 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:56.785 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:57.819 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:58.859 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:05:59.903 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:00.934 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:01.958 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:02.991 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:04.28 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:05.51 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:06.80 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:07.111 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:08.143 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:09.175 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:10.201 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:11.237 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:12.268 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:13.303 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:14.338 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:15.373 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:16.406 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:17.429 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:18.455 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:19.485 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:20.517 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:21.549 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:22.585 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:23.618 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:24.648 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:25.685 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:26.716 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:27.752 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:28.779 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:29.806 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:30.845 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:31.885 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:32.918 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:33.955 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:34.994 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:36.36 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:37.77 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:38.121 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:39.148 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:40.179 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:41.218 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:42.258 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:43.285 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:44.308 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:45.333 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:46.372 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:47.402 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:48.430 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:49.451 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:50.468 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:51.495 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:52.538 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:53.556 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:54.586 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:55.617 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:56.648 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:57.680 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:58.707 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:06:59.735 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:00.767 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:01.804 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:02.822 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:03.860 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:04.892 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:05.914 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:06.945 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:07.980 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:09.17 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:10.51 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:11.82 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:12.119 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:13.156 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:14.198 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:15.233 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:16.268 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:17.304 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:18.334 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:19.370 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:20.403 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:21.439 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:22.471 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:23.507 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:24.540 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:25.573 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:26.607 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:27.638 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:28.665 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:29.702 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:30.744 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:31.772 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:32.806 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:33.839 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:34.863 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:35.894 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:36.928 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:37.980 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:39.20 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:40.48 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:41.74 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:42.105 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:43.140 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:44.171 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:45.208 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:46.249 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:47.285 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:48.317 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:49.345 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:50.379 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:51.406 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:52.442 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:53.481 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:54.514 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:55.553 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:56.592 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:57.633 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:58.668 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:07:59.700 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:00.736 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:01.763 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:02.787 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:03.824 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:04.856 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:05.898 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:06.934 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:07.972 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:09.9 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:10.35 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:11.61 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:12.95 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:13.122 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:14.149 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:15.183 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:16.224 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:17.249 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:18.269 [VCDB-WAL-Backup:PID-47925] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].

2019-09-02T05:08:18.867 [VCDBBackup:PID-45647] INFO: tarCmd = ['/usr/bin/tar', '-cz', '-C', '/', '--ignore-failed-read', '--no-recursion', '--warning', 'no-file-ignored', 'storage/dblog/vpostgres/pg_xlog', 'storage/dblog/vpostgres/pg_xlog/archive_status']

2019-09-02T05:08:19.153 [VCDBBackup:PID-45647] INFO: Stopping Postgres full database backup.

2019-09-02T05:08:19.154 [VCDBBackup:PID-45647] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'select pg_xlogfile_name(pg_stop_backup());'].

2019-09-02T05:08:19.306 [VCDB-WAL-Backup:PID-47925] INFO: VCDB backup stop at WAL file 00000001000000630000002B.

2019-09-02T05:08:19.309 [VCDB-WAL-Backup:PID-47925] INFO: Dispatching 1 WAL files into backup archive: wal_backup_1.tar.gz

2019-09-02T05:08:19.313 [VCDB-WAL-Backup:PID-47925] INFO: tarCmd = ['/usr/bin/tar', '-cz', '-C', '/', '--ignore-failed-read', '-T', '/var/log/vmware/applmgmt/wal_files_q5uw5oyp.lst', '--warning', 'no-file-ignored', '--warning', 'no-file-changed', '--warning', 'no-file-removed']

2019-09-02T05:08:20.234 [VCDB-WAL-Backup:PID-47925] INFO: No WAL files got rotated during backup.

2019-09-02T05:08:20.234 [VCDB-WAL-Backup:PID-47925] INFO: WAL files from 00000001000000630000002B to 00000001000000630000002B were backed up into wal_backup_1.tar.gz successfully.

2019-09-02T05:08:20.238 [VCDB-WAL-Backup:PID-47925] INFO: tarCmd = ['/usr/bin/tar', '-cz', '-C', '/', '--ignore-failed-read', '--warning', 'no-file-ignored', 'dev/shm/all_wal_meta.json']

2019-09-02T05:08:20.512 [VCDB-WAL-Backup:PID-47925] INFO: Verifying all new WAL were backed up.

2019-09-02T05:08:20.513 [VCDB-WAL-Backup:PID-47925] INFO: Completed backup all 1 WAL files from (VCDB backup start)00000001000000630000002B to (VCDB backup stop)00000001000000630000002B.

2019-09-02T05:08:20.516 [VCDBBackup:PID-45647] INFO: WAL backup process completed successfully.

2019-09-02T05:08:20.520 [VCDBBackup:PID-45647] INFO: WAL backup process exited.

2019-09-02T05:08:20.523 [VCDBBackup:PID-45647] INFO: Finishing full database backup

2019-09-02T05:08:20.523 [VCDBBackup:PID-45647] INFO: Retrieving postgres server listening port

2019-09-02T05:08:20.523 [VCDBBackup:PID-45647] INFO: Executing command: netstat -plnt.

2019-09-02T05:08:20.590 [VCDBBackup:PID-45647] INFO: Canceling running pg_start_backup() process.

2019-09-02T05:08:20.591 [VCDBBackup:PID-45647] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', "SELECT pg_cancel_backend(pid) FROM pg_stat_activity WHERE pid <> pg_backend_pid() and query ~ '^select\\ pg_xlogfile_name\\(pg_start_backup\\(.*\\)\\)\\;' "].

2019-09-02T05:08:20.638 [VCDBBackup:PID-45647] INFO: No pg_start_backup() process is running.

2019-09-02T05:08:20.639 [VCDBBackup:PID-45647] INFO: Checking whether Postgres online backup still in progress

2019-09-02T05:08:20.639 [VCDBBackup:PID-45647] INFO: Executing command: /opt/vmware/vpostgres/current/bin/psql -U postgres -p 5432 -t -c "select pg_is_in_backup();".

2019-09-02T05:08:20.664 [VCDBBackup:PID-45647] INFO: Postgres on-line backup already finished. Skip stopping backup operation

2019-09-02T05:08:20.665 [VCDBBackup:PID-45647] INFO: Successfully cleaned up for VCDB backup.

2019-09-03T00:59:52.578 [MainProcess:PID-45427] ERROR: Timeout! Failed to complete in 72000 seconds

2019-09-03T00:59:52.578 [MainProcess:PID-45427] ERROR: BackupManager encountered an exception: Timeout! Failed to complete in 72000 seconds.

2019-09-03T00:59:52.583 [MainProcess:PID-45427] INFO: Cleaning up the backup job.

2019-09-03T00:59:52.583 [MainProcess:PID-45427] INFO: Cleaning up all running backup child processes.

2019-09-03T00:59:52.616 [MainProcess:PID-45427] INFO: Cleaning up all sizeFiles.

2019-09-03T00:59:52.616 [MainProcess:PID-45427] INFO: Cleaning up Lotus.

2019-09-03T00:59:52.616 [MainProcess:PID-45427] INFO: Successfully completed Lotus cleanup.

2019-09-03T00:59:52.616 [MainProcess:PID-45427] INFO: Cleaning up ConfigFiles.

2019-09-03T00:59:52.616 [MainProcess:PID-45427] INFO: Cleaning up VCDB.

2019-09-03T00:59:52.616 [MainProcess:PID-45427] INFO: Finishing full database backup

2019-09-03T00:59:52.616 [MainProcess:PID-45427] INFO: Retrieving postgres server listening port

2019-09-03T00:59:52.616 [MainProcess:PID-45427] INFO: Executing command: netstat -plnt.

2019-09-03T00:59:52.667 [MainProcess:PID-45427] INFO: Canceling running pg_start_backup() process.

2019-09-03T00:59:52.667 [MainProcess:PID-45427] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', "SELECT pg_cancel_backend(pid) FROM pg_stat_activity WHERE pid <> pg_backend_pid() and query ~ '^select\\ pg_xlogfile_name\\(pg_start_backup\\(.*\\)\\)\\;' "].

2019-09-03T00:59:52.700 [MainProcess:PID-45427] INFO: No pg_start_backup() process is running.

2019-09-03T00:59:52.701 [MainProcess:PID-45427] INFO: Checking whether Postgres online backup still in progress

2019-09-03T00:59:52.701 [MainProcess:PID-45427] INFO: Executing command: /opt/vmware/vpostgres/current/bin/psql -U postgres -p 5432 -t -c "select pg_is_in_backup();".

2019-09-03T00:59:52.728 [MainProcess:PID-45427] INFO: Postgres on-line backup already finished. Skip stopping backup operation

2019-09-03T00:59:52.728 [MainProcess:PID-45427] INFO: Successfully cleaned up for VCDB backup.

2019-09-03T00:59:52.729 [MainProcess:PID-45427] INFO: Cleaning up ComponentScripts.

2019-09-03T00:59:52.729 [MainProcess:PID-45427] INFO: Cleaning up StatsMonitorDB.

2019-09-03T00:59:52.729 [MainProcess:PID-45427] INFO: Cleaning up failed backup files.

2019-09-03T00:59:53.682 [MainProcess:PID-45427] INFO: Cleaned up the backup job.

2019-09-03T00:59:54.129 [MainProcess:PID-45427] INFO: Event com.vmware.applmgmt.backup.job.start.failed.event successfully posted to http://localhost:8085/sdk

2019-09-03T00:59:54.136 [MainProcess:PID-45427] INFO: Backup job failed.

ThorstenT · ‎09-10-2019

Looks like the backup for AutoDeploy (rbd) starts but never completes. We run into this issue every couple of weeks. I had hoped for a fix in 6.7U3 but incidentally it came back on one of our production systems last night.

Can you check /var/log/vmware/rbd/rbd-syslog.log for sqlite locking issues? If that's the case, you should be able to fix this by restarting the AutoDeploy service like this:

service-control --restart vmware-rbd-watchdog

rm_bk · ‎05-05-2020

We just ran into this. Restarting that service allowed the hung backup to immediately continue.

kb74737 says it will be fixed in the P01 release. Which release was that? We're on 15976714 at the moment.

berndweyand · ‎05-06-2020

same problem here . vcsa 6.7.0.42200 running for weeks - but since 3 days backup hangs during rbd-backup. restart autodeploy and backup job running successful to the end.

P01 must be 6.7U1

All

VCSA 6.7 Native Backup Fails with Timeout - 72000 seconds reached