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-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.
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
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.
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