3 Replies Latest reply on Dec 11, 2019 8:17 PM by summerof69

    VCSA 6.7 Appliance Native Backup Failing at BackupLotus

    kevanbrown5 Lurker

       

       

       

       

       

       

       

       

      Native appliance backup is configured to use FTPS, and appears to connect successfully to the server.  However, during the backup operation, something in the internal backup process on the appliance fails at 5% with the following error message shown in the GUI: Structure com.vmware.appliance.recovery.backup.job.details.info has a union with a field not required for this case = end_time

       

      The following is the appliance backup.log, start with the first error and continuing to the end:

       

      2018-06-02T16:38:14.855 [LotusBackup:PID-54007] INFO: BackupLotus: Dispatching files ['lock.mdb', 'data.mdb']
      2018-06-02T16:38:14.856 [LotusBackup:PID-54007] INFO: tarCmd = ['/usr/bin/tar', '-cz', '-C', '/tmp/backup_lotus/', '--ignore-failed-read', '--warning', 'no-file-ignored', 'lock.mdb', 'data.mdb']
      2018-06-02T16:38:15.159 [StatsMonitorDBBackup:PID-54009] INFO: Completed backup appliance stats monitor SQLite DB.
      2018-06-02T16:38:15.394 [ConfigFilesBackup:PID-54008] ERROR: Process returncode is -13, but expected exit codes are [0].
      2018-06-02T16:38:15.395 [ConfigFilesBackup:PID-54008] ERROR: rc: 1, stderr: Traceback (most recent call last):
        File "/usr/lib/applmgmt/backup_restore/py/vmware/appliance/backup_restore/plugins/../util/Calculate.py", line 60, in <module>
          main(sys.argv[1], sys.argv[2], sys.argv[3])
        File "/usr/lib/applmgmt/backup_restore/py/vmware/appliance/backup_restore/plugins/../util/Calculate.py", line 47, in main
          stdout_obj.write(data)
      BrokenPipeError: [Errno 32] Broken pipe

      2018-06-02T16:38:15.395 [ConfigFilesBackup:PID-54008] INFO: Skip to report the error.
      2018-06-02T16:38:15.396 [ConfigFilesBackup:PID-54008] ERROR: Process returncode is 1, but expected exit codes are [0].
      2018-06-02T16:38:15.396 [ConfigFilesBackup:PID-54008] ERROR: rc: 56, stderr: b'curl: (56) response reading failed\n'
      2018-06-02T16:38:15.396 [ConfigFilesBackup:PID-54008] ERROR: Failed configuration files backup- rc: -13; stdout: ; stderr:; exception:
      2018-06-02T16:38:15.397 [ConfigFilesBackup:PID-54008] ERROR: Failed configuration files backup
      Underlying process status. rc: -13
      stdout:
      stderr:
      Traceback (most recent call last):
        File "/usr/lib/applmgmt/backup_restore/py/vmware/appliance/backup_restore/components/ConfigFiles.py", line 327, in BackupConfigFiles
          status)
      util.Common.BackupRestoreError: Failed configuration files backup
      Underlying process status. rc: -13
      stdout:
      stderr:
      2018-06-02T16:38:15.498 [LotusBackup:PID-54007] ERROR: Process returncode is -13, but expected exit codes are [0].
      2018-06-02T16:38:15.499 [LotusBackup:PID-54007] ERROR: rc: 1, stderr: Traceback (most recent call last):
        File "/usr/lib/applmgmt/backup_restore/py/vmware/appliance/backup_restore/plugins/../util/Calculate.py", line 60, in <module>
          main(sys.argv[1], sys.argv[2], sys.argv[3])
        File "/usr/lib/applmgmt/backup_restore/py/vmware/appliance/backup_restore/plugins/../util/Calculate.py", line 47, in main
          stdout_obj.write(data)
      BrokenPipeError: [Errno 32] Broken pipe

      2018-06-02T16:38:15.499 [LotusBackup:PID-54007] INFO: Skip to report the error.
      2018-06-02T16:38:15.499 [LotusBackup:PID-54007] ERROR: Process returncode is 1, but expected exit codes are [0].
      2018-06-02T16:38:15.499 [LotusBackup:PID-54007] ERROR: rc: 56, stderr: b'curl: (56) response reading failed\n'
      2018-06-02T16:38:15.500 [LotusBackup:PID-54007] ERROR: Failed to backup Lotus DB
      2018-06-02T16:38:15.500 [LotusBackup:PID-54007] ERROR: Failed to backup Lotus DB
      Underlying process status. rc: -13
      stdout:
      stderr:
      Traceback (most recent call last):
        File "/usr/lib/applmgmt/backup_restore/py/vmware/appliance/backup_restore/components/Lotus.py", line 101, in BackupLotus
          raise BackupRestoreError(err_msg, status)
      util.Common.BackupRestoreError: Failed to backup Lotus DB
      Underlying process status. rc: -13
      stdout:
      stderr:
      2018-06-02T16:38:15.504 [LotusBackup:PID-54007] INFO: Successfully completed Lotus cleanup.
      2018-06-02T16:38:15.680 [MainProcess:PID-53968] ERROR: Error at process LotusBackup; rc:-13.
      2018-06-02T16:38:15.680 [MainProcess:PID-53968] ERROR: stderr:Failed to backup Lotus DB

      2018-06-02T16:38:15.680 [MainProcess:PID-53968] INFO: Following error message isn't localized:
        stderr:Failed to backup Lotus DB

       

      2018-06-02T16:38:15.681 [MainProcess:PID-53968] ERROR: BackupManager encountered an exception: Hit exception inside process LotusBackup:

      2018-06-02T16:38:15.686 [MainProcess:PID-53968] INFO: Cleaning up the backup job.

      2018-06-02T16:38:15.687 [MainProcess:PID-53968] INFO: Cleaning up all running backup child processes.

      2018-06-02T16:38:15.741 [MainProcess:PID-53968] INFO: Cleaning up all sizeFiles.

      2018-06-02T16:38:15.741 [MainProcess:PID-53968] INFO: Cleaning up VCDB.

      2018-06-02T16:38:15.742 [MainProcess:PID-53968] INFO: Finishing full database backup

      2018-06-02T16:38:15.742 [MainProcess:PID-53968] INFO: Retrieving postgres server listening port

      2018-06-02T16:38:15.743 [MainProcess:PID-53968] INFO: Executing command: netstat -plnt.

      2018-06-02T16:38:15.787 [MainProcess:PID-53968] INFO: Canceling running pg_start_backup() process.

      2018-06-02T16:38:15.787 [MainProcess:PID-53968] 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\\(.*\\)\\)\\;' "].

      2018-06-02T16:38:15.823 [MainProcess:PID-53968] INFO: Checking pg_start_backup process was canceled.

      2018-06-02T16:38:15.824 [MainProcess:PID-53968] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/psql', '-U', 'postgres', '-p', '5432', '-At', '-c', "SELECT pid FROM pg_stat_activity WHERE pid <> pg_backend_pid()  and query ~ '^select\\ pg_xlogfile_name\\(pg_start_backup\\(.*\\)\\)\\;' "].

      2018-06-02T16:38:15.857 [MainProcess:PID-53968] INFO: Successfully canceled the pg_start_backup().

      2018-06-02T16:38:15.858 [MainProcess:PID-53968] INFO: Checking whether Postgres online backup still in progress

      2018-06-02T16:38:15.858 [MainProcess:PID-53968] INFO: Executing command: /opt/vmware/vpostgres/current/bin/psql -U postgres -p 5432 -t -c "select pg_is_in_backup();".

      2018-06-02T16:38:15.891 [MainProcess:PID-53968] INFO: Postgres on-line backup already finished. Skip stopping backup operation

      2018-06-02T16:38:15.891 [MainProcess:PID-53968] INFO: Successfully cleaned up for VCDB backup.

      2018-06-02T16:38:15.891 [MainProcess:PID-53968] INFO: Cleaning up Lotus.

      2018-06-02T16:38:15.892 [MainProcess:PID-53968] INFO: Successfully completed Lotus cleanup.

      2018-06-02T16:38:15.892 [MainProcess:PID-53968] INFO: Cleaning up ConfigFiles.

      2018-06-02T16:38:15.892 [MainProcess:PID-53968] INFO: Cleaning up StatsMonitorDB.

      2018-06-02T16:38:15.892 [MainProcess:PID-53968] INFO: Cleaning up ComponentScripts.

      2018-06-02T16:38:15.892 [MainProcess:PID-53968] INFO: Cleaning up failed backup files.

      2018-06-02T16:38:21.138 [MainProcess:PID-53968] WARNING: Ignore to clean up failed backup files, due to issue: 'Failed to list FTP dir with cmd ['/usr/bin/curl', '--fail', '-u', 'vCenter:****', '--connect-timeout', '10', '--ssl-reqd', '-k', '--noproxy', '*', '--silent', '--show-error', '--list-only', 'ftp://ftp.neodev.com/vCenter/sn_vc.neodev.com/M_6.7.0.11000_20180602-163808_/']; ret=9

      stdOut:

      stdErr: curl: (9) Server denied you to change to the given directory

      '.

      2018-06-02T16:38:21.139 [MainProcess:PID-53968] ERROR: Failed to cleanup the backup job. Error: Failed to clean up the backup job.

      2018-06-02T16:38:21.890 [MainProcess:PID-53968] INFO: Event com.vmware.applmgmt.backup.job.start.failed.event successfully posted to http://localhost:8085/sdk

      2018-06-02T16:38:21.908 [MainProcess:PID-53968] INFO: Backup job failed.

      2018-06-02T16:38:21.910 [MainProcess:PID-53968] INFO: Cleaning up the backup job.

      2018-06-02T16:38:21.911 [MainProcess:PID-53968] INFO: Cleaning up all running backup child processes.

      2018-06-02T16:38:21.960 [MainProcess:PID-53968] INFO: Cleaning up all sizeFiles.

      2018-06-02T16:38:21.961 [MainProcess:PID-53968] INFO: Cleaning up VCDB.

      2018-06-02T16:38:21.961 [MainProcess:PID-53968] INFO: Finishing full database backup

      2018-06-02T16:38:21.961 [MainProcess:PID-53968] INFO: Retrieving postgres server listening port

      2018-06-02T16:38:21.962 [MainProcess:PID-53968] INFO: Executing command: netstat -plnt.

      2018-06-02T16:38:22.10 [MainProcess:PID-53968] INFO: Canceling running pg_start_backup() process.

      2018-06-02T16:38:22.11 [MainProcess:PID-53968] 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\\(.*\\)\\)\\;' "].

      2018-06-02T16:38:22.48 [MainProcess:PID-53968] INFO: No pg_start_backup() process is running.

      2018-06-02T16:38:22.49 [MainProcess:PID-53968] INFO: Checking whether Postgres online backup still in progress

      2018-06-02T16:38:22.49 [MainProcess:PID-53968] INFO: Executing command: /opt/vmware/vpostgres/current/bin/psql -U postgres -p 5432 -t -c "select pg_is_in_backup();".

      2018-06-02T16:38:22.83 [MainProcess:PID-53968] INFO: Postgres on-line backup already finished. Skip stopping backup operation

      2018-06-02T16:38:22.83 [MainProcess:PID-53968] INFO: Successfully cleaned up for VCDB backup.

      2018-06-02T16:38:22.83 [MainProcess:PID-53968] INFO: Cleaning up Lotus.

      2018-06-02T16:38:22.84 [MainProcess:PID-53968] INFO: Successfully completed Lotus cleanup.

      2018-06-02T16:38:22.84 [MainProcess:PID-53968] INFO: Cleaning up ConfigFiles.

      2018-06-02T16:38:22.84 [MainProcess:PID-53968] INFO: Cleaning up StatsMonitorDB.

      2018-06-02T16:38:22.84 [MainProcess:PID-53968] INFO: Cleaning up ComponentScripts.

      2018-06-02T16:38:22.84 [MainProcess:PID-53968] INFO: Cleaning up failed backup files.

      2018-06-02T16:38:23.163 [MainProcess:PID-53968] INFO: Cleaned up the backup job.

      (END)