This post is more than 5 years old
1 Rookie
•
48 Posts
0
38826
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
onestoned
1 Rookie
1 Rookie
•
48 Posts
1
June 13th, 2017 05:00
Hello all,
I found the reason and a solution. In in the vbackupd-vddk.log there are these messages which show, that there ports were blocked through a firewall.It was determined that the ESXi hosts did not have port 902 open, to allow vProxy communication for backup/recovery operations.
VDDK: INFO: CnxOpenTCPSocket: Cannot connect to server :902: Connection timed out
VDDK: INFO: CnxAuthdConnect: Returning false because CnxAuthdConnectTCP failed
VDDK: INFO: CnxConnectAuthd: Returning false because CnxAuthdConnect failed
VDDK: INFO: Cnx_Connect: Returning false because CnxConnectAuthd failed
VDDK: INFO: Cnx_Connect: Error message: Failed to connect to server :902
VDDK: WARN: [NFC ERROR] NfcNewAuthdConnectionEx: Failed to connect to peer. Error: Failed to connect to server
:902
VDDK: INFO: NBD_ClientOpen: Couldn't connect to :902 Failed to connect to server
:902
VDDK: INFO: DISKLIB-DSCPTR: : "vpxa-nfc://[xio_lun22_bo1]
/ .vmdk@ :902" : Failed to open NBD extent.
VDDK: INFO: DISKLIB-LINK : "vpxa-nfc://[xio_lun22_bo1]
/ .vmdk@ :902" : failed to open
(NBD_ERR_NETWORK_CONNECT).
VDDK: INFO: DISKLIB-CHAIN : "vpxa-nfc://[xio_lun22_bo1]
/ .vmdk@ :902" : failed to open
(NBD_ERR_NETWORK_CONNECT).
VDDK: INFO: DISKLIB-LIB : Failed to open 'vpxa-nfc://[xio_lun22_bo1]
/ .vmdk@ :902' with flags 0x1e
NBD_ERR_NETWORK_CONNECT (2338).
VDDK: INFO: VixDiskLib: Unable to locate appropriate transport mode to open disk. Error 13 (You do not have access
rights to this file) at 4570.
thanks for your help
Karthik_N1
25 Posts
0
June 12th, 2017 08:00
Most of the VADP cases I have seen this error.
We used to just disable "Client Direct" of clients which have this problem.
Keeping this in mind, check connectivity from vProxy to Data Domain(Ports, lookups) etc.
Also I see that the transport mode used is NBD, you can try hotadd and see how it goes.
Thanks,
Karthik N
onestoned
1 Rookie
1 Rookie
•
48 Posts
0
June 12th, 2017 09:00
thanks a lot.
please keep in mind, it's a VMWare backup with Networker vproxy. There is no possibility to disable "Cleint direct" as we are doing a backup of a VM.
Name resolution is working properly.
Hotadd is not possible, as no disks are visible by the vproxy. So we are using nbd.
any more thoughts?
thanks a lot
Dave_Hannover
3 Posts
0
September 5th, 2020 10:00
I had the issue and this is how I got mine fixed.
Logon to your vCenter and right click on the issued VM, navigate to Tags & custom Attributes click edit custom attributes, delete register EMC vProxy Session and hit ok. Go back to networker, start the the job again and it should work. It work for me.
cheers
David
Pezdaddy
1 Message
0
April 27th, 2021 06:00
since our VMware admins upgraded from vSphere 6.5 to 6.7, we have frequently run into failed VM backups due to this attribute not automatically getting removed. when the cluster was still at v6.5, from the CLI of the vproxy server, running the vmconfig -c "enable-migration" used to clear the lock
we are using networker v19.1 and we are running the same version for the vproxies.
is there an issue (or conflict) with vsphere v6.7 ?
Dave_Hannover
3 Posts
0
April 28th, 2021 02:00
crazyrov
4 Operator
4 Operator
•
1.3K Posts
0
April 28th, 2021 02:00
@Pezdaddy, According to the compatibility matric VMware 6.7 is compatible with NW 19.1 with vProxy 4.0.0-x, 4.3.0-x. Check this link for more details - https://elabnavigator.emc.com/vault/pdf/NW_All_19_1.pdf?key=1612451110407
Dave_Hannover
3 Posts
0
April 28th, 2021 02:00
barry_beckers
393 Posts
0
May 3rd, 2021 13:00
the ProxyHC tool is also very helpful to solve some issues that can occur with vproxy based backups by being able to perform various checks from the vproxy end towards the backup infra and the VC specifically.
ftp://ftp.legato.com/pub/NetWorker/NVP/Tools/ProxyHC
the ProxyHC tool:
https://youtu.be/dlutigOJLGg
You out the tool onto a vproxy and run it as root. it can be used to check connectivity towards VC, datadomain and the ESXi hosts, VC permissions, get rid of orphaned processes, get rid of vmdk's still assigned to the vproxy and more.
Been using it for some time already and also reached out directly to the Dell developer whose contact info is stated in the tool output. On request for example he added functionality to use it in a scripted way instead of only interactive.