Unable to backup vCenter using SFTP

[Adam42R]

I have been having consistent issues trying to run backups from vcenter. The errors look the same as Not able to backup vCenter From VAMI using SFTP (81782) (vmware.com) but that indicates it should have been fixed in update 2 about 9 months ago. 

I am on:

Product: VMware vCenter Server

Version: 7.0.3.00500

Build number: 19480866

On VM:ESXi 7.0 U2 and later (Version 19)
On Host:ESXi 7.0 U2 and later (Version 19)

2022-04-02T00:15:36.337 [20220402-041531-19480866] [MainProcess:PID-121016] [FtpStorageIOLib::_process_curl_output:FtpStorageIOLib.py:129] ERROR: sftp cmd failed. RC: 78, Err: curl: (78) Could not open directory for reading: No such file or directory, Cmd: ['/usr/bin/curl', '--fail', '-u', 'ftpuser:****', '--connect-timeout', '10', '--ssl-reqd', '-k', '--noproxy', '*', '--silent', '--show-error', '--list-only', 'sftp://[ip.addr]/ftpuser/ftpuser/sn_ftpuser.network.net/M_7.0.3.00500_20220402-041531_/']
2022-04-02T00:15:36.337 [20220402-041531-19480866] [MainProcess:PID-121016] [BackupManager::Cleanup:BackupManager.py:430] WARNING: Ignore to clean up failed backup files, due to issue: 'Plugin error occurred. ErrCode: 3, Args: ()'.
2022-04-02T00:15:36.338 [20220402-041531-19480866] [MainProcess:PID-121016] [BackupManager::HandleBackupCleanup:BackupManager.py:474] ERROR: Failed to cleanup the backup job. Error: Failed to clean up the backup job.
2022-04-02T00:15:36.641 [20220402-041531-19480866] [MainProcess:PID-121016] [vpxdevent_lib::dispatch_events:vpxdevent_lib.py:275] INFO: Event com.vmware.applmgmt.backup.job.failed.event successfully posted to http://localhost:8085/sdk
2022-04-02T00:15:36.646 [20220402-041531-19480866] [MainProcess:PID-121016] [BackupManager::main:BackupManager.py:682] INFO: Backup job failed.

 

I am able to ssh to vCenter and can both sftp from the command line and run curl -v [sftp]. In both cases, I am using the same account I am using to try run backups. The first connects fine and I can create a directory fine. I delete that and run the curl -v and that too works fine showing authentication complete. But the errors above are on every try to run the backup from vcenter itself. I assume this is a simple me issue but would love to have some insight as to what it is. 

[Swetha Nagarudraiah]

Hi Adam42R ,

Can you please confirm if you are trying to do Manual Backup or a Scheduled backup? Also if you can share logs under /var/log/vmware/applmgmt it will help to understand the issue better

[Adam42R]

The scheduled backup setup does not show errors, this however is doing manual backups. The excerpt above is from /var/log/vmware/applmgmt/backup.log. I can try pull that full section at lunch and update it here.

To clarify, the scheduled backup setup does not show errors, it however has never run. The errors are from running the manual backup using the config from the backup schedule.

[Adam42R]

Here's a transcript of a failed sftp manual backup:

2022-04-04T12:48:32.797 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::main:BackupManager.py:624] INFO: Starting backup job...
2022-04-04T12:48:32.798 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::main:BackupManager.py:633] INFO: Manual Backup triggerd
2022-04-04T12:48:32.798 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::main:BackupManager.py:639] INFO: DB health check enabled status is True
2022-04-04T12:49:05.826 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::getDbHealthStatus:BackupManager.py:514] INFO: getDbHealthStatus returns status as HEALTHY
2022-04-04T12:49:05.826 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::HealthCheckStatus:BackupManager.py:533] INFO: DB is healthy, proceed with backup
2022-04-04T12:49:05.885 [20220404-164832-19480866] [MainProcess:PID-106964] [ComponentScripts::ComponentScriptsSize:ComponentScripts.py:31] INFO: Calculate size for components
2022-04-04T12:49:06.597 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::CheckFileIntegrity:BackupManager.py:452] INFO: File integrity check is not enabled.
2022-04-04T12:49:06.911 [20220404-164832-19480866] [MainProcess:PID-106964] [SftpStorageIOLib::_addHostToKnownhosts:SftpStorageIOLib.py:219] INFO: Added remote host key to known hosts file
2022-04-04T12:49:06.912 [20220404-164832-19480866] [MainProcess:PID-106964] [SftpStorageIOLib::_readRemoteRoot:SftpStorageIOLib.py:145] INFO: Executing command to get remote root: ssh -q -p 22 -i /root/.ssh/id_rsa -o UserKnownHostsFile=/root/.ssh/br_temp_known_hosts [e-mail] echo ~
2022-04-04T12:49:06.965 [20220404-164832-19480866] [MainProcess:PID-106964] [SftpStorageIOLib::_authorizeLocalHost:SftpStorageIOLib.py:168] INFO: Authorizing localhost with command sshpass -f /tmp/tmppz7p9d3b ssh-copy-id -i /root/.ssh/id_rsa.pub -p 22 -o UserKnownHostsFile=/root/.ssh/br_temp_known_hosts [e-mail]
2022-04-04T12:49:07.91 [20220404-164832-19480866] [MainProcess:PID-106964] [SftpStorageIOLib::_authorizeLocalHost:SftpStorageIOLib.py:174] ERROR: Failed to authorize local host with command: sshpass -f /tmp/tmppz7p9d3b ssh-copy-id -i /root/.ssh/id_rsa.pub -p 22 -o UserKnownHostsFile=/root/.ssh/br_temp_known_hosts [e-mail]. Will proceed with backup through curl
2022-04-04T12:49:07.92 [20220404-164832-19480866] [MainProcess:PID-106964] [SftpStorageIOLib::_readRemoteRoot:SftpStorageIOLib.py:145] INFO: Executing command to get remote root: ssh -q -p 22 -i /root/.ssh/id_rsa -o UserKnownHostsFile=/root/.ssh/br_temp_known_hosts [e-mail] echo ~
2022-04-04T12:49:08.612 [20220404-164832-19480866] [MainProcess:PID-106964] [SftpStorageIOLib::mkdir:SftpStorageIOLib.py:345] WARNING: Parent dir sftp://coral.labnet.com/vCenter create failed. RC: 21 Err: curl: (21) mkdir command failed: Permission denied

2022-04-04T12:49:09.368 [20220404-164832-19480866] [MainProcess:PID-106964] [SftpStorageIOLib::mkdir:SftpStorageIOLib.py:345] WARNING: Parent dir sftp://coral.labnet.com/vCenter/sn_vcenter.labnet.com create failed. RC: 21 Err: curl: (21) mkdir command failed: No such file or directory

2022-04-04T12:49:09.744 [20220404-164832-19480866] [MainProcess:PID-106964] [FtpStorageIOLib::_process_curl_output:FtpStorageIOLib.py:123] ERROR: sftp quote cmd failed. Err: curl: (21) mkdir command failed: No such file or directory
, Cmd: ['/usr/bin/curl', '--fail', '-u', 'sftpuser:****', '--connect-timeout', '10', '--ssl-reqd', '-k', '--noproxy', '*', '--silent', '--show-error', '-Q', 'mkdir /vCenter/sn_vcenter.labnet.com/M_7.0.3.00500_20220404-164832_/', 'sftp://coral.labnet.com/vCenter/sn_vcenter.labnet.com/']
2022-04-04T12:49:09.745 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::CreateTargetBackupDir:BackupManager.py:111] ERROR: Failed to create backup directory Plugin error occurred. ErrCode: 3, Args: ()
2022-04-04T12:49:09.745 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::main:BackupManager.py:659] ERROR: BackupManager encountered an exception: Failed to create backup directory on backup server.
2022-04-04T12:49:09.745 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::HandleBackupCleanup:BackupManager.py:466] INFO: Cleaning up the backup job.
2022-04-04T12:49:09.746 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::Cleanup:BackupManager.py:402] INFO: Cleaning up all running backup child processes.
2022-04-04T12:49:09.759 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::Cleanup:BackupManager.py:409] INFO: Cleaning up all sizeFiles.
2022-04-04T12:49:09.759 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::Cleanup:BackupManager.py:417] INFO: Cleaning up ConfigFiles.
2022-04-04T12:49:09.759 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::Cleanup:BackupManager.py:417] INFO: Cleaning up ComponentScripts.
2022-04-04T12:49:09.759 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::Cleanup:BackupManager.py:417] INFO: Cleaning up VCDB.
2022-04-04T12:49:09.760 [20220404-164832-19480866] [MainProcess:PID-106964] [VCDB::BackupVCDBCleanup:VCDB.py:2100] INFO: Finishing full database backup
2022-04-04T12:49:09.767 [20220404-164832-19480866] [MainProcess:PID-106964] [VCDB::BackupVCDBCleanup:VCDB.py:2103] INFO: Successfully cleaned up for VCDB backup.
2022-04-04T12:49:09.767 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::Cleanup:BackupManager.py:417] INFO: Cleaning up Lotus.
2022-04-04T12:49:09.767 [20220404-164832-19480866] [MainProcess:PID-106964] [Lotus::BackupLotusCleanup:Lotus.py:140] INFO: Successfully completed Lotus cleanup.
2022-04-04T12:49:09.767 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::Cleanup:BackupManager.py:417] INFO: Cleaning up StatsMonitorDB.
2022-04-04T12:49:09.767 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::Cleanup:BackupManager.py:417] INFO: Cleaning up VTSDB.
2022-04-04T12:49:09.768 [20220404-164832-19480866] [MainProcess:PID-106964] [VTSDB::BackupVTSDBCleanup:VTSDB.py:237] INFO: Successfully cleaned up for VTSDB backup.
2022-04-04T12:49:09.768 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::Cleanup:BackupManager.py:426] INFO: Cleaning up failed backup files.
2022-04-04T12:49:10.150 [20220404-164832-19480866] [MainProcess:PID-106964] [FtpStorageIOLib::_process_curl_output:FtpStorageIOLib.py:129] ERROR: sftp cmd failed. RC: 78, Err: curl: (78) Could not open directory for reading: No such file or directory
, Cmd: ['/usr/bin/curl', '--fail', '-u', 'sftpuser:****', '--connect-timeout', '10', '--ssl-reqd', '-k', '--noproxy', '*', '--silent', '--show-error', '--list-only', 'sftp://coral.labnet.com/vCenter/sn_vcenter.labnet.com/M_7.0.3.00500_20220404-164832_/']
2022-04-04T12:49:10.150 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::Cleanup:BackupManager.py:430] WARNING: Ignore to clean up failed backup files, due to issue: 'Plugin error occurred. ErrCode: 3, Args: ()'.
2022-04-04T12:49:10.150 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::HandleBackupCleanup:BackupManager.py:474] ERROR: Failed to cleanup the backup job. Error: Failed to clean up the backup job.
2022-04-04T12:49:10.431 [20220404-164832-19480866] [MainProcess:PID-106964] [vpxdevent_lib::dispatch_events:vpxdevent_lib.py:275] INFO: Event com.vmware.applmgmt.backup.job.failed.event successfully posted to http://localhost:8085/sdk
2022-04-04T12:49:10.436 [20220404-164832-19480866] [MainProcess:PID-106964] [BackupManager::main:BackupManager.py:682] INFO: Backup job failed.

 

This is my running the same two commands that fail above from the vcenter shell, key diff is me seeding the tmp_mypwd with the pwd.

root@vcenter [ ~ ]# sshpass -f /tmp/tmp_mypwd ssh-copy-id -i /root/.ssh/id_rsa.pub -p 22 -o UserKnownHostsFile=/root/.ssh/br_temp_known_hosts [e-mail]
/usr/bin/ssh-copy-id: INFO: Source of key(s) to be installed: "/root/.ssh/id_rsa.pub"
/usr/bin/ssh-copy-id: INFO: attempting to log in with the new key(s), to filter out any that are already installed

/usr/bin/ssh-copy-id: WARNING: All keys were skipped because they already exist on the remote system.
(if you think this is a mistake, you may want to use -f option)

root@vcenter [ ~ ]# ssh -q -p 22 -i /root/.ssh/id_rsa -o UserKnownHostsFile=/root/.ssh/br_temp_known_hosts [e-mail]
Welcome to Ubuntu 20.04.4 LTS (GNU/Linux 5.13.0-39-generic x86_64)

* Documentation: https://help.ubuntu.com
* Management: https://landscape.canonical.com
* Support: https://ubuntu.com/advantage

0 updates can be applied immediately.

Your Hardware Enablement Stack (HWE) is supported until April 2025.
Last login: Mon Apr 4 21:31:31 2022 from [vcenter ipaddress]
$

 

Again, I am assuming this is a me issue, I am just not readily seeing what it is.

 

[Shital Patil]

HI Adam42R,

Thanks for sharing the logs. The issue looks different from the KB.
Could you please share the sftp logs for further analysis.

Could you please try running the below  command from VCSA to take backup . 

 '/usr/bin/curl', '--fail', '-u', 'sftpuser:****', '--connect-timeout', '10', '--ssl-reqd', '-k', '--noproxy', '*', '--silent', '--show-error', '-Q', 'mkdir vCenter/sn_vcenter.labnet.com/M_7.0.3.00500_20220404-164832_/', 'sftp://coral.labnet.com/vCenter/sn_vcenter.labnet.com/'

Also could you please try taking backup with different protocol . FTP,FTPS,HTTPS,HTTP,SMB,NFS these all are supported .

 

 

 

 

 

[Adam42R]

The issue is the fixed path that vCenter is using (/vCenter). The path you are using above is fine as it is relative to sftpuser's home directory.  If you use the path provided by vCenter, it's absolute off the root. Is that standard that vCenter requires an SFTP root directory of /vCenter/? Any way to change that to a relative vCenter/ directory off of the account's directory? 

/usr/bin/curl --fail -u "sftpuser:****" --connect-timeout 10 --ssl-reqd -k --noproxy * --silent --show-error -Q', "mkdir /vCenter/sn_vcenter.labnet.com/M_7.0.3.00500_20220404-164832_/" "sftp://coral.labnet.com/vCenter/sn_vcenter.labnet.com/"