CpuHotRemoveEnabled ?!

Was playing around enabling CPU & Memory Hot Add via PowerCli/PowerShell, and came across the CPUHotRemoveEnabled feature.

<pre>$VMSpec=New-Object -Type VMware.Vim.VirtualMachineConfigSpec -Property @{"CpuHotRemoveEnabled" =  $true}
$VM = Get-VM W2K16GA
$VM.ExtensionData.ReconfigVM_Task($VMSpec)</pre>

This feature may be around for ages, I personally never used it. And as far as I know is still unsupported.. Tried it with a Windows 2016 Enterprise Edition VM, but no sigar. Both the GUI and PowerCli didn’t allow changes to be made. Could scale up CPUs but unable to scale down.

(The screenshot below doesn’t show CPU Hot Plug as Enabled, but CPU Hot Remove fails regardless of CPU Hot Plug being Enabled or not)

PowerCli error:

Set-VM W2K16GA -NumCpu 1
The operation for the entity "W2K16GA" failed with the following message: "CPU hot plug is not supported for this virtual machine."

So don’t know if this post is useful for anybody, but I smiled while playing around with this. 🙂

But if you enable it on a VM in 6.5 you get a prevously hidden check box:

Enable CPU Hot Remove checkbox visible

The ye olde fatclient also had this option (picture blatenly stolen from somewhere)

Advertisement

VCSA Native Backup Logging

Just a little post about logging.

VMware’s example script logs to backup.log in the directory the script is ran from.

However I just placed the script in /etc/cron.daily/ and it will only log when the script is started by a user. Started by Cron, it doesn’t log to this file.

However there is logging available at:

/storage/log/vmware/applmgmt/backupRestoreAPI.log which contains some condensed information:

2017-03-07 03:49:02,628 [MainProcess:PID-40796] INFO: The location provided: ftps://123.123.123.123/backup/2017-03-07-03-49-02
2017-03-07 03:49:02,814 [MainProcess:PID-40796] INFO: The backup dir does not exist
2017-03-07 03:49:04,993 [MainProcess:PID-40796] INFO: List of stopped services: [u'imagebuilder', u'vmcam', u'mbcs', u'vcha', u'netdumper', u'rbd']
2017-03-07 03:52:58,694 [MainProcess:PID-40796] INFO: Checking whether the backup job completed or not.
2017-03-07 03:52:58,695 [MainProcess:PID-40796] INFO: Backup job completed with the state 'SUCCEEDED'.

and

/storage/log/vmware/applmgmt/backup.log which is much more verbose:

2017-03-07 03:49:05,290 [MainProcess:PID-37567] INFO: The location provided: ftps://123.123.123.123/backup/2017-03-07-03-49-02
2017-03-07 03:49:05,314 [MainProcess:PID-37567] INFO: Starting backup job...
2017-03-07 03:49:08,476 [MainProcess:PID-37567] INFO: The backup dir does not exist
2017-03-07 03:49:08,538 [MainProcess:PID-37567] INFO: Started backup at UTC: 2017-03-07 02:49:08.439122
2017-03-07 03:49:08,546 [ConfigFilesBackup:PID-37615] INFO: Started with configuration files backup.
2017-03-07 03:49:08,546 [LotusBackup:PID-37616] INFO: Starting backup Lotus
2017-03-07 03:49:08,548 [StatsMonitorDBBackup:PID-37619] INFO: Starting backup appliance monitor SQLite DB.
2017-03-07 03:49:08,549 [StatsMonitorDBBackup:PID-37619] INFO: Appliance Stats Monitor database file path: /var/vmware/applmgmt/appliance_stats.sqlite
2017-03-07 03:49:08,549 [StatsMonitorDBBackup:PID-37619] INFO: Executing command sqlite3 /var/vmware/applmgmt/appliance_stats.sqlite .dump.
2017-03-07 03:49:08,550 [LotusBackup:PID-37616] INFO: BackupLotus: Running /usr/lib/vmware-vmdir/bin/vdcbackup /storage/db/vmware-vmdir/ /tmp/backup_lotus/
2017-03-07 03:49:08,552 [VCDBBackup:PID-37617] INFO: Retrieving postgres server listening port
2017-03-07 03:49:08,552 [VCDBBackup:PID-37617] INFO: Executing command: netstat -plnt.
2017-03-07 03:49:08,558 [ComponentScriptsBackup:PID-37618] INFO: Starting backup component: imagebuilder
2017-03-07 03:49:08,559 [ComponentScriptsBackup:PID-37618] INFO: Execute imagebuilder script: /etc/vmware/backup/component-scripts/imagebuilder/backup_restore.py --startBackup
2017-03-07 03:49:08,562 [ComponentScriptsBackup:PID-37618] INFO: Dispatching stream.
2017-03-07 03:49:08,643 [VCDBBackup:PID-37617] INFO: Starting VCDB full database backup
2017-03-07 03:49:08,644 [VCDBBackup:PID-37617] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', u"select pg_xlogfile_name(pg_start_backup('backup_20170307_024905_4944578'));"].
2017-03-07 03:49:08,797 [ConfigFilesBackup:PID-37615] INFO: incl: /var/log/vmware/applmgmt/cfg_incl_3Swc3b.lst excl: /var/log/vmware/applmgmt/cfg_excl_1lUKkw.lst
2017-03-07 03:49:08,798 [ConfigFilesBackup:PID-37615] INFO: tarCmd = tar -cz -C / --ignore-failed-read -T "/var/log/vmware/applmgmt/cfg_incl_3Swc3b.lst" -X "/var/log/vmware/applmgmt/cfg_excl_1lUKkw.lst" --warning="no-file-ignored"
2017-03-07 03:49:08,856 [ComponentScriptsBackup:PID-37618] INFO: Component imagebuilder backup successful.
2017-03-07 03:49:08,857 [ComponentScriptsBackup:PID-37618] INFO: Starting backup component: vum
2017-03-07 03:49:08,858 [ComponentScriptsBackup:PID-37618] INFO: Execute vum script: /etc/vmware/backup/component-scripts/vum/backup_restore.py --startBackup
2017-03-07 03:49:08,861 [ComponentScriptsBackup:PID-37618] INFO: Dispatching stream.
2017-03-07 03:49:10,115 [StatsMonitorDBBackup:PID-37619] INFO: Completed backup appliance stats monitor SQLite DB.
2017-03-07 03:49:17,742 [LotusBackup:PID-37616] INFO: stdout: BackupDB: Setting vmdir state to VMDIRD_READ_ONLY
BackupDB: Backing up: /storage/db/vmware-vmdir//data.mdb
BackupDB: Backing up: /storage/db/vmware-vmdir//lock.mdb
BackupDB: Setting vmdir state to VMDIRD_NORMAL

2017-03-07 03:49:17,742 [LotusBackup:PID-37616] INFO: BackupLotus: Dispatching files ['lock.mdb', 'data.mdb']
2017-03-07 03:49:17,742 [LotusBackup:PID-37616] INFO: tarCmd = tar -cz -C /tmp/backup_lotus/ --ignore-failed-read --warning="no-file-ignored" "lock.mdb" "data.mdb"
2017-03-07 03:49:28,855 [LotusBackup:PID-37616] INFO: Lotus backup finished successfully.
2017-03-07 03:49:28,961 [LotusBackup:PID-37616] INFO: Cleaning up Vmdir. Running /usr/lib/vmware-vmdir/bin/vdcbackup -c
2017-03-07 03:49:29,043 [LotusBackup:PID-37616] INFO: stdout: Cleanup: Setting vmdir state to VMDIRD_NORMAL

2017-03-07 03:49:29,043 [LotusBackup:PID-37616] INFO: Cleaning up Vmdir. Running /usr/lib/vmware-vmdir/bin/vdcbackup -c
2017-03-07 03:49:29,129 [LotusBackup:PID-37616] INFO: stdout: Cleanup: Setting vmdir state to VMDIRD_NORMAL

2017-03-07 03:49:33,757 [VCDBBackup:PID-37617] INFO: Successfully start Postgres on-line backup window.
2017-03-07 03:49:33,757 [VCDBBackup:PID-37617] INFO: Backup start WAL file is 0000000100000003000000FF.
2017-03-07 03:49:33,759 [VCDBBackup:PID-37617] INFO: tarCmd = 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"
2017-03-07 03:49:33,760 [VCDB-WAL-Backup:PID-37920] INFO: Starting backup WAL files.
2017-03-07 03:49:33,761 [VCDB-WAL-Backup:PID-37920] INFO: VCDB backup start at WAL file 0000000100000003000000FF.
2017-03-07 03:49:33,761 [VCDB-WAL-Backup:PID-37920] INFO: Each WAL backup image contains 5 WAL files.
2017-03-07 03:49:34,762 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:35,787 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:36,819 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:37,864 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:38,890 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:39,917 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:40,941 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:41,964 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:42,984 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:44,003 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:45,052 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:46,068 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:47,088 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:48,110 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:49,130 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:50,153 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:51,172 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:52,194 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:53,233 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:54,262 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:55,276 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:56,293 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:57,331 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:58,347 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:49:59,399 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:00,416 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:01,439 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:02,478 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:03,508 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:04,524 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:05,548 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:06,564 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:07,597 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:08,616 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:09,643 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:10,658 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:11,699 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:12,720 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:13,740 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:14,762 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:15,788 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:16,822 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:17,836 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:18,853 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:19,905 [VCDB-WAL-Backup:PID-37920] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'SELECT pg_xlogfile_name(pg_current_xlog_location());'].
2017-03-07 03:50:20,574 [VCDBBackup:PID-37617] INFO: tarCmd = tar -cz -C / --ignore-failed-read --no-recursion --warning="no-file-ignored" "storage/dblog/vpostgres/pg_xlog" "storage/dblog/vpostgres/pg_xlog/archive_status"
2017-03-07 03:50:20,675 [VCDBBackup:PID-37617] INFO: Stopping Postgres full database backup.
2017-03-07 03:50:20,675 [VCDBBackup:PID-37617] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', 'select pg_xlogfile_name(pg_stop_backup());'].
2017-03-07 03:50:20,940 [VCDB-WAL-Backup:PID-37920] INFO: VCDB backup stop at WAL file 0000000100000003000000FF.
2017-03-07 03:50:20,941 [VCDB-WAL-Backup:PID-37920] INFO: Dispatching 1 WAL files into backup archive: wal_backup_1.tar.gz.enc
2017-03-07 03:50:20,943 [VCDB-WAL-Backup:PID-37920] INFO: tarCmd = tar -cz -C / --ignore-failed-read -T "/var/log/vmware/applmgmt/wal_files_s0gPyD.lst" --warning="no-file-ignored" --warning="no-file-changed" --warning="no-file-removed"
2017-03-07 03:50:21,290 [VCDB-WAL-Backup:PID-37920] INFO: No WAL files got rotated during backup.
2017-03-07 03:50:21,290 [VCDB-WAL-Backup:PID-37920] INFO: WAL files from 0000000100000003000000FF to 0000000100000003000000FF were backed up into wal_backup_1.tar.gz.enc successfully.
2017-03-07 03:50:21,290 [VCDB-WAL-Backup:PID-37920] INFO: tarCmd = tar -cz -C / --ignore-failed-read --warning="no-file-ignored" "dev/shm/all_wal_meta.json"
2017-03-07 03:50:21,422 [VCDB-WAL-Backup:PID-37920] INFO: Verifying all new WAL were backed up.
2017-03-07 03:50:21,422 [VCDB-WAL-Backup:PID-37920] INFO: Completed backup all 1 WAL files from (VCDB backup start)0000000100000003000000FF to (VCDB backup stop)0000000100000003000000FF.
2017-03-07 03:50:21,423 [VCDBBackup:PID-37617] INFO: WAL backup process completed successfully.
2017-03-07 03:50:21,424 [VCDBBackup:PID-37617] INFO: WAL backup process exited.
2017-03-07 03:50:21,425 [VCDBBackup:PID-37617] INFO: Finishing full database backup
2017-03-07 03:50:21,426 [VCDBBackup:PID-37617] INFO: Retrieving postgres server listening port
2017-03-07 03:50:21,426 [VCDBBackup:PID-37617] INFO: Executing command: netstat -plnt.
2017-03-07 03:50:21,458 [VCDBBackup:PID-37617] INFO: Canceling running pg_start_backup() process.
2017-03-07 03:50:21,458 [VCDBBackup:PID-37617] 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 query ~ '^pg_start_backup'"].
2017-03-07 03:50:21,478 [VCDBBackup:PID-37617] INFO: No pg_start_backup() process is running.
2017-03-07 03:50:21,478 [VCDBBackup:PID-37617] INFO: Checking whether Postgres online backup still in progress
2017-03-07 03:50:21,478 [VCDBBackup:PID-37617] INFO: Executing command: /opt/vmware/vpostgres/current/bin/psql -U postgres -p 5432 -t -c "select pg_is_in_backup();".
2017-03-07 03:50:21,495 [VCDBBackup:PID-37617] INFO: Postgres on-line backup already finished. Skip stopping backup operation
2017-03-07 03:50:21,496 [VCDBBackup:PID-37617] INFO: Successfully cleaned up for VCDB backup.
2017-03-07 03:52:23,502 [ComponentScriptsBackup:PID-37618] INFO: Component vum backup successful.
2017-03-07 03:52:23,503 [ComponentScriptsBackup:PID-37618] INFO: Starting backup component: rbd
2017-03-07 03:52:23,504 [ComponentScriptsBackup:PID-37618] INFO: Execute rbd script: /etc/vmware/backup/component-scripts/rbd/rbd-backup-restore --startBackup
2017-03-07 03:52:23,507 [ComponentScriptsBackup:PID-37618] INFO: Dispatching stream.
2017-03-07 03:52:23,642 [ComponentScriptsBackup:PID-37618] INFO: Component rbd backup successful.
2017-03-07 03:52:58,009 [ConfigFilesBackup:PID-37615] ERROR: rc: 0, stderr: tar: usr/lib/vmware-vpx/endpoints/vimapi-endpoint.xml: Warning: Cannot stat: No such file or directory
tar: etc/vmware-vsm/wrapper/wrapper_java_additional.conf: Warning: Cannot stat: No such file or directory
tar: var/lib/vmware/vmcam/ssl/certs: Warning: Cannot stat: No such file or directory
tar: etc/vmware-eam/version: Warning: Cannot stat: No such file or directory
tar: usr/lib/vmware-vpx/sps/wrapper/conf/wrapper_java_additional.conf: Warning: Cannot stat: No such file or directory
tar: usr/etc/systemd/user: Warning: Cannot stat: No such file or directory
tar: storage/db/vmware-vmdir/snapshot: Warning: Cannot stat: No such file or directory
tar: usr/lib/vmware-vcha/data/pg_hba_block.conf: Warning: Cannot stat: No such file or directory
tar: usr/lib/vmware-vmafd/share/config/krb5.keytab: Warning: Cannot stat: No such file or directory
tar: usr/lib/vmware-vcha/data/pg-firewall-block.conf: Warning: Cannot stat: No such file or directory
tar: usr/lib/vmware-vpx/endpoints/qs-endpoint.xml: Warning: Cannot stat: No such file or directory
tar: etc/vmware/appliance/firewall/ccm-firewall.conf: Warning: Cannot stat: No such file or directory

2017-03-07 03:52:58,010 [ConfigFilesBackup:PID-37615] INFO: Successfully finished configuration files backup.
2017-03-07 03:52:58,481 [MainProcess:PID-37567] INFO: PNID 'knvcenter.local.raadvanstate.nl' is resolved with addrInfo: [(2, 1, 6, '', ('234.234.234.234', 0)), (2, 2, 17, '', ('234.234.234.234', 0)), (2, 3, 0, '', ('234.234.234.234', 0))]
2017-03-07 03:52:58,482 [MainProcess:PID-37567] INFO: Generating password validator in metadata.
2017-03-07 03:52:58,482 [MainProcess:PID-37567] INFO: Executing command: ['openssl', 'aes-256-cbc', '-e', '-k', '****', '-base64'].
2017-03-07 03:52:58,488 [MainProcess:PID-37567] INFO: Password validator: Uadsf%$dGVkdasf5d5adsfv4aL2E97IHnNq45agaxadsfUJs9A9AoEFlb4LeA2U
sYWWH3+DUOwlazxvi58mpydsVihL5AQAkgiO8jKWfFg=
2017-03-07 03:52:58,488 [MainProcess:PID-37567] INFO: The location provided: ftps://123.123.123.123/backup/2017-03-07-03-49-02
2017-03-07 03:52:58,671 [MainProcess:PID-37567] ERROR: Failed to make the files readonly at ftp://123.123.123.123/backup/2017-03-07-03-49-02/; Err- Failed to execute command '['curl', '--fail', '-u', u'ftpuser@local.domain:****', '--connect-timeout', '10', '--ssl-reqd', '-k', '--silent', '--show-error', '-Q', u'SITE chmod 444 backup/2017-03-07-03-49-02/backup-metadata.json', u'ftp://123.123.123.123/']' at 'ftp://123.123.123.123/'; ret=21
stdOut:
stdErr: curl: (21) QUOT command failed with 500

2017-03-07 03:52:58,672 [MainProcess:PID-37567] INFO: Finished backup at UTC: 2017-03-07 02:52:58.671633. Duration: 230 seconds.
2017-03-07 03:52:58,678 [MainProcess:PID-37567] INFO: Backup job finished successfully.

 

The message:

tar: etc/vmware-eam/version: Warning: Cannot stat: No such file or directory

seam to be safe to ignore. Saw these on multiple VCSA servers. (Same version 6.5A (build 5200)

Same goes for this message:

ERROR: Failed to make the files readonly at ftp://123.123.123.123/backup/2017-03-07-03-49-02/

Since the FTP server is a Windows (IIS) server, it does not support chmod. On my homelab (using a Synology NAS as FTP server) this message doesn’t show.

 

 

 

Setting up FTPS server for VCSA backup

I followed the steps in Backing up vCSA 6.5 natively using FTPS but wasn’t able to create a backup succesfully.

It seemed that I could login to the ftps server with FileZilla client, but it wasn’t able to list the directories on the FTPS server. Didn’t really noticed the warnings in FileZilla, since the directories were empty 🙂

However FileZilla complained:

Status: Connecting to 1.2.3.4:21...
Status: Connection established, waiting for welcome message...
Status: Initializing TLS...
Status: Verifying certificate...
Status: TLS connection established.
Status: Logged in
Status: Retrieving directory listing...
Command: PWD
Response: 257 "/" is current directory.
Command: TYPE I
Response: 200 Type set to I.
Command: PASV
Response: 227 Entering Passive Mode (1,2,3,4,208,227).
Command: LIST
Response: 150 Opening BINARY mode data connection.
Error: Connection timed out
Error: Failed to retrieve directory listing
Status: Disconnected from server

Grant Curell blogged about this error (look for Fixing Problem #2 on the blog) the issue was with the internal Windows firewall in Windows 2012 R2.

Also Using the buildin (Predefined) FTP Server rules didn’t work:

Not working Build-In Predefined FTP Server rule

I’ve created two firewall rules, allowing ports 20,21,990, 55000-56000 in both UDP and TCP.

Two of these Port rules, One for TCP one for UDP.

I set the Data Channel Port Range from 55000 to 56000. This setting is done on the IIS node, not on the FTP site.

Data Channel Port Range setting (entire IIS server, not just the FTP site)

After a restart of the FTP server service, I could now connect. And the backup now finishes succesfully.

Status: Connecting to 1.2.3.4:21...
Status: Connection established, waiting for welcome message...
Status: Initializing TLS...
Status: Verifying certificate...
Status: TLS connection established.
Status: Logged in
Status: Retrieving directory listing...
Status: Directory listing of "/" successful

VCSA 6.5 Native Backup Bash Script

VMware published a demo bash script to initiate a VCSA backup. It can be found here.

Maybe it’s my browser, but just copy ‘n pasting didn’t work, every line after the first is indented by a space. Rendering the herestring defunkt. Giving me this error:

{"value":"f4395605a992fb62827bad75ed4f43ee"}./backupvcsa.sh: line 75: warning: here-document at line 20 delimited by end-of-file (wanted `EOF')
awk: fatal: cannot open file `response.txt' for reading (No such file or directory)

Just remove the space in front of EOL:

cat << EOF >task.json
 { "piece":
      {
          "location_type":"FTP",
          "comment":"Automatic backup",
          "parts":["seat"],
          "location":"ftp://$FTP_ADDRESS/$BACKUP_FOLDER/$TIME",
          "location_user":"$FTP_USER",
          "location_password":"$FTP_PASSWORD"
      }
 }
EOF # Remove the space before this line!

Removing the space leading the EOF fixed my issue.

The demo script uses FTP, and doesn’t encrypt the backup file. In the environment I’m working in, we needed the backup to be encrypted, and send over FTPS.

So I just tried to change FTP to FTPS on lines 24 and 28, and that worked fine. The other supported protocols are just as easy to use: just enter FTP, FTPS, HTTP, HTTPS or SCP

Hersey Cartwright over at vHersey.com blogged about changing the script to use SCP. You can find it here. His script contains more usefull stuf!

Searching the documentation or the api help in the VCSA itself didn’t help, they suggested that the parameter may be called backup-password or backupPassword like in the API cli:

Command> help api com.vmware.appliance.recovery.backup.job.create

Usage:
 com.vmware.appliance.recovery.backup.job.create [--help/-h]
 --backupPassword NEW_PASSWORD_STR --locationType ENUM
 --locationPassword PASSWORD_STR --comment STR --parts STR
 --location STR --locationUser STR
Description:
 Initiate backup.
Input Arguments:
 --backupPassword NEW_PASSWORD_STR
 a password for a backup piece The backupPassword must adhere
 to the following password requirements: At least 8
 characters, cannot be more than 20 characters in length. At
 least 1 uppercase letter. At least 1 lowercase letter. At
 least 1 numeric digit. At least 1 special character (i.e.
 any character not in [0-9,a-z,A-Z]). Only visible ASCII
 characters (for example, no space).

But the biggest hint was given by the already listed parameters, where words are connected with an underscore like in location_password. Trying this worked.

Once I found this I Googled “backup_password” and found this piece of REST API documentation.

UPDATE: I’ve updated the VCSA and discovered that the backup hasn’t run. The calling script was still in /etc/cron.daily/ and was executable, however the actual backup script I had placed in /root/. That file also still exists, but lost it’s executable bit… Needed chmod +x.

After this the backup job would start, but finishes very fast, no data was transferred. Looking at the logs in /storage/log/vmware/applmgmt/backupRestoreAPI.log showed an error:

 ERROR: All required services are not up! Stopped services: 'statsmonitor'.

Using service-control I started the service, the backup now runs again.

root@vcenter [ / ]# service-control --start statsmonitor
Perform start operation. vmon_profile=None, svc_names=['statsmonitor'], include_coreossvcs=False, include_leafossvcs=False
YYYY-MM-DDTHH:MM:SS.mmmZ Service statsmonitor state STOPPED
Successfully started service statsmonitor