1 Reply Latest reply on Sep 10, 2019 12:42 AM by ThorstenT

    VCSA 6.7 Native Backup Fails with Timeout - 72000 seconds reached

    MSchaff Lurker

      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-045913_

      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.

        • 1. Re: VCSA 6.7 Native Backup Fails with Timeout - 72000 seconds reached
          ThorstenT Novice

          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