This post is more than 5 years old
1 Rookie
•
49 Posts
0
39445
June 12th, 2017 07:00
vproxy backup fails
Hello all,
I configured NW 9.1.1.1 to backup VMs with vproxy solution in nbd mode on vSphere 6.5. But the backup attempt always fails with these messages. I ensured the datastore is accessable and the configured user has full permission. So the message "VDDK Error: 13: You do not have access rights to this file." is misleading I tried different VMs. Used storage Motion to migrate a VM. A manual snapshot is also possible.
What can we do to troubleshott this? Any ideas? Thanks a lot in advance.
error messages are highlighted in red.
2017/06/12 16:09:15 NOTICE: [145] Logging to '/opt/emc/vproxy/runtime/logs/vbackupd/f29a4f8c-2070-4082-aef5-0a16415ff6fd.log' on host 'vm-vproxy-1'
2017/06/12 16:09:15 NOTICE: [145] Release: '2.0.2-11_1', Build number: '1', Build date: '2017-03-30T18:46:12Z'
2017/06/12 16:09:15 TRACE: [145] Using locale "en", 67 messages.
2017/06/12 16:09:15 NOTICE: [145] Starting backup of "vm-cltsuport-01" (vm-201) logging at level "TRACE" ...
2017/06/12 16:09:15 NOTICE: [145] BackupVmSessions supplied by client:
2017/06/12 16:09:15 NOTICE: [145] {
2017/06/12 16:09:15 NOTICE: [145] "Config": {
2017/06/12 16:09:15 NOTICE: [145] "SessionId": "f29a4f8c-2070-4082-aef5-0a16415ff6fd",
2017/06/12 16:09:15 NOTICE: [145] "LogTag": "145",
2017/06/12 16:09:15 NOTICE: [145] "LogLevel": "TRACE",
2017/06/12 16:09:15 NOTICE: [145] "IdleTimeout": 300,
2017/06/12 16:09:15 NOTICE: [145] "AcceptedLanguage": "en",
2017/06/12 16:09:15 NOTICE: [145] "TransportModeRequested": "nbd",
2017/06/12 16:09:15 NOTICE: [145] "Parallelism": 1,
2017/06/12 16:09:15 NOTICE: [145] "UseCbt": true,
2017/06/12 16:09:15 NOTICE: [145] "VimServerRef": {
2017/06/12 16:09:15 NOTICE: [145] "HostName": "vm-vcenter-1",
2017/06/12 16:09:15 NOTICE: [145] "TcpPort": 0,
2017/06/12 16:09:15 NOTICE: [145] "UserName": "sa.networker@vsphere.local",
2017/06/12 16:09:15 NOTICE: [145] "UserPassword": "********",
2017/06/12 16:09:15 NOTICE: [145] "ThumbPrint": ""
2017/06/12 16:09:15 NOTICE: [145] },
2017/06/12 16:09:15 NOTICE: [145] "VmSpec": {
2017/06/12 16:09:15 NOTICE: [145] "Name": "vm-cltsuport-01",
2017/06/12 16:09:15 NOTICE: [145] "VmMoref": "vm-201",
2017/06/12 16:09:15 NOTICE: [145] "VirtualDisks": [
2017/06/12 16:09:15 NOTICE: [145] {
2017/06/12 16:09:15 NOTICE: [145] "Label": "Festplatte 1",
2017/06/12 16:09:15 NOTICE: [145] "Key": 2000
2017/06/12 16:09:15 NOTICE: [145] }
2017/06/12 16:09:15 NOTICE: [145] ],
2017/06/12 16:09:15 NOTICE: [145] "CustomFieldName": "Last EMC vProxy Backup",
2017/06/12 16:09:15 NOTICE: [145] "CustomFieldValue": "Backup Server=vm-backup-01, Policy=VMWare, Workflow=VMWare Tag, Action=backup, JobId=64052"
2017/06/12 16:09:15 NOTICE: [145] },
2017/06/12 16:09:15 NOTICE: [145] "SnapshotSpec": {
2017/06/12 16:09:15 NOTICE: [145] "Name": "NetWorker Backup Snapshot",
2017/06/12 16:09:15 NOTICE: [145] "Description": "Snapshot is created as part of protecting this VM by EMC NetWorker VProxy.",
2017/06/12 16:09:15 NOTICE: [145] "Quiesce": false,
2017/06/12 16:09:15 NOTICE: [145] "DumpMemory": false,
2017/06/12 16:09:15 NOTICE: [145] "RemoveAll": false,
2017/06/12 16:09:15 NOTICE: [145] "Consolidate": false
2017/06/12 16:09:15 NOTICE: [145] },
2017/06/12 16:09:15 NOTICE: [145] "TargetSpec": {
2017/06/12 16:09:15 NOTICE: [145] "DeviceType": "DataDomain",
2017/06/12 16:09:15 NOTICE: [145] "HostName": "og2-dd-01.xxx-yyyyy.com",
2017/06/12 16:09:15 NOTICE: [145] "UserName": "OST_USER",
2017/06/12 16:09:15 NOTICE: [145] "UserPassword": "********",
2017/06/12 16:09:15 NOTICE: [145] "BackupMode": "VSS",
2017/06/12 16:09:15 NOTICE: [145] "BackupPath": "backup/VMWare//backup/VMWare/57/73/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656",
2017/06/12 16:09:15 NOTICE: [145] "PreviousBackupPath": "",
2017/06/12 16:09:15 NOTICE: [145] "CurrentBackupPath": "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656",
2017/06/12 16:09:15 NOTICE: [145] "VBABackup": {
2017/06/12 16:09:15 NOTICE: [145] "VBABackupPath": "",
2017/06/12 16:09:15 NOTICE: [145] "VBATempPath": ""
2017/06/12 16:09:15 NOTICE: [145] }
2017/06/12 16:09:15 NOTICE: [145] },
2017/06/12 16:09:15 NOTICE: [145] "ZeroFillUnusedSectors": false,
2017/06/12 16:09:15 NOTICE: [145] "AutoEnableCbt": true,
2017/06/12 16:09:15 NOTICE: [145] "AutoRepairCbt": true,
2017/06/12 16:09:15 NOTICE: [145] "FallbackCbtThreshold": 0,
2017/06/12 16:09:15 NOTICE: [145] "FallbackTransportMode": "",
2017/06/12 16:09:15 NOTICE: [145] "DeprecatedREST": false,
2017/06/12 16:09:15 NOTICE: [145] "ReadBufferMB": 0,
2017/06/12 16:09:15 NOTICE: [145] "WriteBufferKB": 0,
2017/06/12 16:09:15 NOTICE: [145] "BufferCount": 0
2017/06/12 16:09:15 NOTICE: [145] },
2017/06/12 16:09:15 NOTICE: [145] "Actions": {
2017/06/12 16:09:15 NOTICE: [145] "ChangeSession": "",
2017/06/12 16:09:15 NOTICE: [145] "DeleteSession": "/api/v1/BackupVmSessions/f29a4f8c-2070-4082-aef5-0a16415ff6fd",
2017/06/12 16:09:15 NOTICE: [145] "CancelActivity": "/api/v1/BackupVmSessions/f29a4f8c-2070-4082-aef5-0a16415ff6fd/activity",
2017/06/12 16:09:15 NOTICE: [145] "GetSession": "/api/v1/BackupVmSessions/f29a4f8c-2070-4082-aef5-0a16415ff6fd",
2017/06/12 16:09:15 NOTICE: [145] "GetSessionLog": "/api/v1/BackupVmSessions/f29a4f8c-2070-4082-aef5-0a16415ff6fd/log",
2017/06/12 16:09:15 NOTICE: [145] "GetAllSessions": "/api/v1/BackupVmSessions"
2017/06/12 16:09:15 NOTICE: [145] },
2017/06/12 16:09:15 NOTICE: [145] "Status": {
2017/06/12 16:09:15 NOTICE: [145] "State": "Queued",
2017/06/12 16:09:15 NOTICE: [145] "Description": "",
2017/06/12 16:09:15 NOTICE: [145] "Progress": 0,
2017/06/12 16:09:15 NOTICE: [145] "Error": {
2017/06/12 16:09:15 NOTICE: [145] "Text": "",
2017/06/12 16:09:15 NOTICE: [145] "Code": 0
2017/06/12 16:09:15 NOTICE: [145] },
2017/06/12 16:09:15 NOTICE: [145] "StartTime": "",
2017/06/12 16:09:15 NOTICE: [145] "EndTime": "",
2017/06/12 16:09:15 NOTICE: [145] "BytesToMove": 0,
2017/06/12 16:09:15 NOTICE: [145] "BytesMoved": 0,
2017/06/12 16:09:15 NOTICE: [145] "TransportModeUsed": "",
2017/06/12 16:09:15 NOTICE: [145] "BackupModeUsed": ""
2017/06/12 16:09:15 NOTICE: [145] }
2017/06/12 16:09:15 NOTICE: [145] }
2017/06/12 16:09:15 TRACE: [145] Set state to running.
2017/06/12 16:09:15 TRACE: [145] Sent initial status to vProxy Engine.
2017/06/12 16:09:15 TRACE: [145] Opening session to target device "og2-dd-01.xxx-yyyyy.com" ...
2017/06/12 16:09:15 TRACE: [145] Starting go routine to listen for cancel from vProxy engine.
2017/06/12 16:09:15 TRACE: [145] Starting go routine to periodically send status updates...
2017/06/12 16:09:15 NOTICE: [145] DD Model = "DD2500", DDOS Version = "Data Domain OS 5.7.4.0-552828", DD Boost Version = "3.3.0.4-550644".
2017/06/12 16:09:15 TRACE: [145] Opened session to target device "og2-dd-01.xxx-yyyyy.com".
2017/06/12 16:09:15 INFO: [145] DDOS version 5.7.4.0-552828 compatible.
2017/06/12 16:09:15 TRACE: [145] Verifying that target directory "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656" on "og2-dd-01.xxx-yyyyy.com" is empty.
2017/06/12 16:09:15 TRACE: [145] Opening target directory "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656" on DD "og2-dd-01.xxx-yyyyy.com".
2017/06/12 16:09:16 INFO: [145] Opened target directory "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656" on DD "og2-dd-01.xxx-yyyyy.com".
2017/06/12 16:09:16 TRACE: [145] Closing target directory "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656" on DD "og2-dd-01.xxx-yyyyy.com".
2017/06/12 16:09:16 INFO: [145] Closed target directory "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656" on DD "og2-dd-01.xxx-yyyyy.com".
2017/06/12 16:09:16 INFO: [145] Connected to session on vCenter 'vm-vcenter-1' Version '6.5.0 build-5318154, API:6.5', Uuid:d9803871-c47d-4bb2-bcfe-2d9e62f2929b.
2017/06/12 16:09:16 TRACE: [145] Searching for virtual machine with MORef "vm-201" ...
2017/06/12 16:09:16 TRACE: [145] Querying vCenter for definition of virtual machine with MORef of "vm-201" ...
2017/06/12 16:09:16 INFO: [145] Found virtual machine "vm-cltsuport-01" with MORef "vm-201".
2017/06/12 16:09:16 TRACE: [145] Check host'hsrz-esxvw-2.xxx-yyyyy.com' connectionState:'connected',inMaintenanceMode:'false', powerState:poweredOn
2017/06/12 16:09:16 INFO: [145] Host 'hsrz-esxvw-2.xxx-yyyyy.com' is running VMware ESXi 6.5.0 Build-5310538.
2017/06/12 16:09:16 INFO: [145] Locking VM.
2017/06/12 16:09:16 TRACE: [145] Setting custom attribute 'EMC vProxy Session' value for object vm-201 to 'Operation=Backup, StartTime=2017-06-12T14:09:15Z, vProxy=vm-vproxy-1, SessionId=f29a4f8c-2070-4082-aef5-0a16415ff6fd' ...
2017/06/12 16:09:16 INFO: [145] Set custom attribute 'EMC vProxy Session' value for object vm-201 to 'Operation=Backup, StartTime=2017-06-12T14:09:15Z, vProxy=vm-vproxy-1, SessionId=f29a4f8c-2070-4082-aef5-0a16415ff6fd'.
2017/06/12 16:09:17 TRACE: [145] Checking for old snapshots to cleanup ...
2017/06/12 16:09:17 TRACE: [145] No pre-existing snapshots found.
2017/06/12 16:09:17 INFO: [145] Disabling storage migration of virtual machine ...
2017/06/12 16:09:17 TRACE: [145] Disabling storage migration of virtual machine "vm-201" ...
2017/06/12 16:09:18 NOTICE: [145] Storage migration successfully disabled: "vm-201" @ "vm-vcenter-1"
2017/06/12 16:09:18 INFO: [145] Creating snapshot of virtual machine ...
2017/06/12 16:09:18 TRACE: [145] Sending create snapshot request to Snapshot Manager ...
2017/06/12 16:09:19 INFO: [145] Create snapshot request succeeded.
2017/06/12 16:09:19 INFO: [145] Found snapshot "snapshot-246".
2017/06/12 16:09:19 TRACE: [145] Checking CBT for "Festplatte 1" (disk key = 2000).
2017/06/12 16:09:19 NOTICE: [145] VM passed configuration checks.
2017/06/12 16:09:19 TRACE: [145] Checking for leftover VDDK tmp directory "/tmp/vmware-root/564d7f95-f15c-8a69-0ab9-f1d7ad136a02-vm-201" ...
2017/06/12 16:09:19 TRACE: [145] VDDK tmp directory "/tmp/vmware-root/564d7f95-f15c-8a69-0ab9-f1d7ad136a02-vm-201" doesn't exist.
2017/06/12 16:09:19 TRACE: [145] Opening VDDK connection to "vm-201" @ "vm-vcenter-1" using "nbd" ...
2017/06/12 16:09:19 INFO: [145] Opened VDDK connection to "vm-201"@"vm-vcenter-1".
2017/06/12 16:09:19 INFO: [145] Opened VDDK connection to "vm-201"@"vm-vcenter-1".
2017/06/12 16:09:19 TRACE: [145] Getting Virtual Machine Config ...
2017/06/12 16:09:19 TRACE: [145] Getting 2 Virtual Machine Config File Descriptor ...
2017/06/12 16:09:19 TRACE: [145] Downloading "[SW1-VMFS-INT-DATASTORE-03] vm-cltsuport-01/vm-cltsuport-01.vmx" and saving to "vm-201-config-file-0.cfg" ...
2017/06/12 16:09:20 INFO: [145] Created VM configuration file "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656/vm-201-config-file-0.cfg".
2017/06/12 16:09:20 TRACE: [145] Finding folder with MORef "group-v3" ...
2017/06/12 16:09:20 INFO: [145] Found folder "vm" with MORef "group-v3".
2017/06/12 16:09:20 TRACE: [145] Finding datacenter with MORef "datacenter-2" ...
2017/06/12 16:09:20 INFO: [145] Found datacenter "datacenter-vw" having MORef "datacenter-2".
2017/06/12 16:09:20 TRACE: [145] Downloading contents of config file from URL "https://vm-vcenter-1/folder/vm-cltsuport-01/vm-cltsuport-01.vmx?dcPath=datacenter-vw&dsName=SW1-VMFS-INT-DATASTORE-03"
2017/06/12 16:09:20 TRACE: [145] Creating HTTP Get request to download contents of config file "[SW1-VMFS-INT-DATASTORE-03] vm-cltsuport-01/vm-cltsuport-01.vmx".
2017/06/12 16:09:20 TRACE: [145] Starting download contents of config file "[SW1-VMFS-INT-DATASTORE-03] vm-cltsuport-01/vm-cltsuport-01.vmx".
2017/06/12 16:09:20 INFO: [145] Downloaded contents of config file "[SW1-VMFS-INT-DATASTORE-03] vm-cltsuport-01/vm-cltsuport-01.vmx".
2017/06/12 16:09:20 TRACE: [145] Closing VM configuration file "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656/vm-201-config-file-0.cfg" ...
2017/06/12 16:09:20 INFO: [145] Closed VM configuration file "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656/vm-201-config-file-0.cfg" ...
2017/06/12 16:09:20 TRACE: [145] Downloading "[SW1-VMFS-INT-DATASTORE-03] vm-cltsuport-01/vm-cltsuport-01.nvram" and saving to "vm-201-config-file-1.cfg" ...
2017/06/12 16:09:20 INFO: [145] Created VM configuration file "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656/vm-201-config-file-1.cfg".
2017/06/12 16:09:20 TRACE: [145] Finding folder with MORef "group-v3" ...
2017/06/12 16:09:20 INFO: [145] Found folder "vm" with MORef "group-v3".
2017/06/12 16:09:20 TRACE: [145] Finding datacenter with MORef "datacenter-2" ...
2017/06/12 16:09:20 INFO: [145] Found datacenter "datacenter-vw" having MORef "datacenter-2".
2017/06/12 16:09:20 TRACE: [145] Downloading contents of config file from URL "https://vm-vcenter-1/folder/vm-cltsuport-01/vm-cltsuport-01.nvram?dcPath=datacenter-vw&dsName=SW1-VMFS-INT-DATASTORE-03"
2017/06/12 16:09:20 TRACE: [145] Creating HTTP Get request to download contents of config file "[SW1-VMFS-INT-DATASTORE-03] vm-cltsuport-01/vm-cltsuport-01.nvram".
2017/06/12 16:09:20 TRACE: [145] Starting download contents of config file "[SW1-VMFS-INT-DATASTORE-03] vm-cltsuport-01/vm-cltsuport-01.nvram".
2017/06/12 16:09:21 INFO: [145] Downloaded contents of config file "[SW1-VMFS-INT-DATASTORE-03] vm-cltsuport-01/vm-cltsuport-01.nvram".
2017/06/12 16:09:21 TRACE: [145] Closing VM configuration file "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656/vm-201-config-file-1.cfg" ...
2017/06/12 16:09:21 INFO: [145] Closed VM configuration file "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656/vm-201-config-file-1.cfg" ...
2017/06/12 16:09:21 TRACE: [145] Querying CBT data relative to "*" start sector 0, for "Festplatte 1".
2017/06/12 16:09:21 NOTICE: [145] CBT reports 15998648320 bytes changed, 157 change blocks.
2017/06/12 16:09:21 INFO: [145] Queried CBT data relative to "*", for "Festplatte 1".
2017/06/12 16:09:21 INFO: [145] Queried Used Block metadata for "Festplatte 1".
2017/06/12 16:09:21 TRACE: [145] Opening Change Descriptor file "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656/vm-201-disk-key-2000-used-blocks.json" ...
2017/06/12 16:09:21 INFO: [145] Opened Change Descriptor file "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656/vm-201-disk-key-2000-used-blocks.json" ...
2017/06/12 16:09:21 INFO: [145] Saved Change Descriptor file "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656/vm-201-disk-key-2000-used-blocks.json".
2017/06/12 16:09:21 TRACE: [145] Closing Change Descriptor file "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656/vm-201-disk-key-2000-used-blocks.json" ...
2017/06/12 16:09:21 INFO: [145] Closed Change Descriptor file "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656/vm-201-disk-key-2000-used-blocks.json" ...
2017/06/12 16:09:21 INFO: [145] Saved Used Block metadata for "Festplatte 1" to "/backup/VMWare/active/afbcf8f8-00000006-943ea08d-593ea08d-006d5000-5447b656/vm-201-disk-key-2000-used-blocks.json".
2017/06/12 16:09:21 TRACE: [145] Backing up 1 virtual disks...
2017/06/12 16:09:21 TRACE: [145] vimDisks = map[2000:0xc8201d61e0], key = 2000
2017/06/12 16:09:21 INFO: [145] "Festplatte 1": BackupVmdk: Starting full backup ...
2017/06/12 16:09:21 TRACE: [145] "Festplatte 1": BackupVmdk: Initializing VMDK for backup.
2017/06/12 16:09:21 TRACE: [145] "Festplatte 1": BackupVmdk: Opening Virtual Disk ...
2017/06/12 16:09:21 TRACE: [145] Opening source VMDK "[SW1-VMFS-INT-DATASTORE-03] vm-cltsuport-01/vm-cltsuport-01.vmdk" ...
2017/06/12 16:09:21 INFO: [145] Calling VixDiskLib_Open("[SW1-VMFS-INT-DATASTORE-03] vm-cltsuport-01/vm-cltsuport-01.vmdk")...
2017/06/12 16:09:21 ERROR: [145] VDDK Error: 13: You do not have access rights to this file.
2017/06/12 16:09:22 ERROR: [145] Failed to open source VMDK "[SW1-VMFS-INT-DATASTORE-03] vm-cltsuport-01/vm-cltsuport-01.vmdk".
2017/06/12 16:09:22 ERROR: [145] "Festplatte 1": BackupVmdk: "Festplatte 1": Unable to open Virtual Disk "[SW1-VMFS-INT-DATASTORE-03] vm-cltsuport-01/vm-cltsuport-01.vmdk" in "nbd" mode.
2017/06/12 16:09:22 ERROR: [145] "Festplatte 1": BackupVmdk: "Festplatte 1": Unable to open Virtual Disk "[SW1-VMFS-INT-DATASTORE-03] vm-cltsuport-01/vm-cltsuport-01.vmdk" in "nbd" mode.
2017/06/12 16:09:22 ERROR: [145] "Festplatte 1": BackupVmdk: Failed backup.
2017/06/12 16:09:22 ERROR: [145] Unable to backup virtual disk "Festplatte 1".
2017/06/12 16:09:22 TRACE: [145] BackupVM detected close of channel VmdkBackupSession::ReadStatUpdates.
2017/06/12 16:09:22 TRACE: [145] BackupVM detected close of channel VmdkBackupSession::StateDescription.
2017/06/12 16:09:22 TRACE: [145] BackupVM detected close of channel VmdkBackupSession::WriteStatUpdates.
2017/06/12 16:09:22 INFO: [145] Disconnecting VDDK from "vm-201" @ "vm-vcenter-1"...
2017/06/12 16:09:22 INFO: [145] Closed VDDK connection to "vm-201"@"vm-vcenter-1".
2017/06/12 16:09:22 INFO: [145] Closed VDDK connection to "vm-201"@"vm-vcenter-1".
2017/06/12 16:09:22 INFO: [145] No disks of target virtual machine were attached to vProxy's virtual machine.
2017/06/12 16:09:22 TRACE: [145] Checking for leftover VDDK tmp directory "/tmp/vmware-root/564d7f95-f15c-8a69-0ab9-f1d7ad136a02-vm-201" ...
2017/06/12 16:09:22 TRACE: [145] VDDK tmp directory "/tmp/vmware-root/564d7f95-f15c-8a69-0ab9-f1d7ad136a02-vm-201" doesn't exist.
2017/06/12 16:09:22 TRACE: [145] Sending remove snapshot request to Snapshot Manager ...
2017/06/12 16:09:22 INFO: [145] Remove snapshot request accepted by Snapshot Manager.
2017/06/12 16:09:22 INFO: [145] Enabling storage migration of virtual machine ...
2017/06/12 16:09:22 TRACE: [145] Enabling storage migration for "vm-201" ...
2017/06/12 16:09:22 INFO: [145] Storage migration successfully enabled: "vm-201" @ "vm-vcenter-1"
2017/06/12 16:09:22 TRACE: [145] Unlocking VM ...
2017/06/12 16:09:22 TRACE: [145] Attemp #1 to clear virtual machine's custom field lock "EMC vProxy Session" ...
2017/06/12 16:09:22 TRACE: [145] Setting custom attribute 'EMC vProxy Session' value for object vm-201 to '' ...
2017/06/12 16:09:22 INFO: [145] Set custom attribute 'EMC vProxy Session' value for object vm-201 to ''.
2017/06/12 16:09:22 INFO: [145] Unlocked virtual machine.
2017/06/12 16:09:22 INFO: [145] Disconnected from session on vCenter 'vm-vcenter-1'.
2017/06/12 16:09:22 TRACE: [145] Closing session with target device "og2-dd-01.xxx-yyyyy.com" ...
2017/06/12 16:09:22 INFO: [145] Closed session with target device "og2-dd-01.xxx-yyyyy.com".
2017/06/12 16:09:22 TRACE: [145] Checking final status...
2017/06/12 16:09:22 TRACE: [145] Set state to failed.
2017/06/12 16:09:22 ERROR: [145] Backup has FAILED.
2017/06/12 16:09:22 TRACE: [145] Sending final status to vProxy Engine ...
2017/06/12 16:09:22 INFO: [145] Sent final status to vProxy Engine.
2017/06/12 16:09:22 INFO: [145] Go routine sending status updates has completed.
2017/06/12 16:09:22 INFO: [145] Go routine listening for cancel messages from vProxy engine has completed.
2017/06/12 16:09:22 NOTICE: [145] Backup session is exiting