- VMware Technology Network
- :
- VMware {code}
- :
- Virtual Disk Development Kit
- :
- Virtual Disk Development Kit Discussions
- :
- VDDK 6.7.1 : Received unexpected message: NFC_SESS...
- Subscribe to RSS Feed
- Mark Topic as New
- Mark Topic as Read
- Float this Topic for Current User
- Bookmark
- Subscribe
- Mute
- Printer Friendly Page
- Mark as New
- Bookmark
- Subscribe
- Mute
- Subscribe to RSS Feed
- Permalink
- Report Inappropriate Content
VDDK 6.7.1 : Received unexpected message: NFC_SESSION_COMPLETE from server. Expected message: NFC_FSSRVR_DISKGEO
I am using cgo wrappers in golang to make calls to vddk. The disk open call seems to be occasionally failing with the error :
Received unexpected message: NFC_SESSION_COMPLETE from server. Expected message: NFC_FSSRVR_DISKGEO
If I retry the call after waiting for some time, it generally succeeds. Sometimes, I see that it does not succeed even after 3 retries.
Any idea what could be going wrong ? I am using the latest version of VDDK ( 6.7.1 - build 0362358 )
Logs :
2018-11-21T22:51:53.087617+00:00 I vddk.go:145] VixDiskLibVim: Extract datastore from VMX path [MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk.
2018-11-21T22:51:53.088006+00:00 I vddk.go:145] VixDiskLibVim: Skip leading character(s).
2018-11-21T22:51:53.088607+00:00 I vddk.go:145] VixDiskLibVim: Retrieved datastore from VMX path.
2018-11-21T22:51:53.089029+00:00 I vddk.go:145] VixDiskLibVim: Disk found.
2018-11-21T22:51:53.089612+00:00 I vddk.go:145] VixDiskLibVim: Get device key operation is done.
2018-11-21T22:51:53.090061+00:00 I vddk.go:145] VixDiskLibVim: Start loading internal service content object.
2018-11-21T22:51:53.090598+00:00 I vddk.go:145] VixDiskLibVim: Loading internal service content is done.
2018-11-21T22:51:53.091038+00:00 I vddk.go:145] VixDiskLibVim: Callback for loading VM object completes.
2018-11-21T22:51:53.126330+00:00 I vddk.go:145] VixDiskLibVim: Load the internal service instance and retrieve NFC service.
2018-11-21T22:51:53.126736+00:00 I vddk.go:145] VixDiskLibVim: Successfully retrieved internal service instance.
2018-11-21T22:51:53.127043+00:00 I vddk.go:145] VixDiskLibVim: Issue an NFC ticket request for VM and DiskKey: 2000.
2018-11-21T22:51:53.127384+00:00 I vddk.go:145] VixDiskLibVim: Request RandomAccessRO diskKey = 2000, readOnly = 1, openSnapshot = 0.
2018-11-21T22:51:53.127780+00:00 I vddk.go:145] VixDiskLibVim: Load internal service instance callback is done.
2018-11-21T22:51:53.176855+00:00 I vddk.go:145] VixDiskLibVim: Callback for opening disk: [MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk using NFC.
2018-11-21T22:51:53.177576+00:00 I vddk.go:145] VixDiskLibVim: Attempt to copy NFC ticket data.
2018-11-21T22:51:53.179072+00:00 I vddk.go:145] VixDiskLibVim: Ticket data copied successfully.
2018-11-21T22:51:53.179713+00:00 I vddk.go:145] VixDiskLibVim: Logout ticket queue.
2018-11-21T22:51:53.180170+00:00 I vddk.go:145] VixDiskLibVim: Opening disk using NFC callback is done.
2018-11-21T22:51:53.180870+00:00 I vddk.go:145] VixDiskLibVim: Logout from server.
2018-11-21T22:51:53.181532+00:00 I vddk.go:145] VixDiskLibVim: Clean up callback data.
2018-11-21T22:51:53.183308+00:00 I vddk.go:145] VixDiskLibVim: Logout from server is done.
2018-11-21T22:51:53.222957+00:00 I vddk.go:145] VixDiskLibVim: Clean up after logging out from server.
2018-11-21T22:51:53.223326+00:00 I vddk.go:145] VixDiskLibVim: Logout callback is done.
2018-11-21T22:51:53.223796+00:00 I vddk.go:145] VixDiskLibVim: Clean up callback data.
2018-11-21T22:51:53.224072+00:00 I vddk.go:145] VixDiskLibVim: VixDiskLibVimFreeInternalVCAboutInfo: Free Internal VC AboutInfo.
2018-11-21T22:51:53.224329+00:00 I vddk.go:145] VixDiskLibVim: Get NFC ticket completed.
2018-11-21T22:51:53.224647+00:00 I vddk.go:145] VixDiskLib: Check if xodus-qa-01.eng.mycompany.com is in memory database.
2018-11-21T22:51:53.224844+00:00 I vddk.go:145] VixDiskLib: Thumbprint for xodus-qa-01.eng.mycompany.com not found in memory database.
2018-11-21T22:51:53.225060+00:00 I vddk.go:145] VixDiskLib: Load thumbprint.
2018-11-21T22:51:53.225489+00:00 I vddk.go:145] VixDiskLib: Open sslIdDb.
2018-11-21T22:51:53.225690+00:00 I vddk.go:145] VixDiskLib: Add thumbprint.
2018-11-21T22:51:53.225881+00:00 I vddk.go:145] VixDiskLib: Added thumbprint 77:8E:98:BA:94:26:31:A9:C5:DF:AA:BC:F7:A3:08:FD:14:2D:2A:C2 to sslIdDb for xodus-qa-01.eng.mycompany.com.
2018-11-21T22:51:53.226098+00:00 I vddk.go:145] VixDiskLib: Close sslIdDb.
2018-11-21T22:51:53.226511+00:00 I vddk.go:145] VixDiskLib: Release sslIdDb.
2018-11-21T22:51:53.226727+00:00 I vddk.go:145] VixDiskLib: Push crypto key to host: xodus-qa-01.eng.mycompany.com.
2018-11-21T22:51:53.227114+00:00 I vddk.go:145] VixDiskLibVim: VixDiskLibVim_HandleDiskCryptoKey: handle the key of disk [MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk.
2018-11-21T22:51:53.227567+00:00 I vddk.go:145] VixDiskLibVim: VixDiskLibVim_HandleDiskCryptoKey: no need to handle crypto key for VMX spec.
2018-11-21T22:51:53.227814+00:00 I vddk.go:145] VixDiskLib: Get full path to: [MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk.
2018-11-21T22:51:53.228199+00:00 I vddk.go:145] VixDiskLib: Release NFC ticket.
2018-11-21T22:51:53.228637+00:00 I vddk.go:145] VixDiskLibVim: VixDiskLibVim_FreeNfcTicket: Free NFC ticket.
2018-11-21T22:51:53.228913+00:00 I vddk.go:145] VixDiskLibVim: VixDiskLibVim_FreeFileName: Free file name.
2018-11-21T22:51:53.229138+00:00 I vddk.go:145] VixDiskLib: Open disk: FASTLZ-vpxa-nfc://[MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk@xodus-qa-01.eng.mycompany.com:902!52 58 19 63 63 d6 88 92-31 4d 90 29 9f aa ec 63.
2018-11-21T22:51:53.229506+00:00 I vddk.go:145] NBD_ClientOpen: attempting to create connection to FASTLZ-vpxa-nfc://[MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk@xodus-qa-01.eng.mycompany.com:902!52 58 19 63 63 d6 88 92-31 4d 90 29 9f aa ec 63
2018-11-21T22:51:53.229708+00:00 I vddk.go:145] [NFC DEBUG] Using proxy/session authentication, sessionId=52 58 19 63 63 d6 88 92-31 4d 90 29 9f aa ec 63, useSSL=0
2018-11-21T22:51:53.229972+00:00 I vddk.go:145] [NFC INFO] Plain-text connection is deprecated; use SSL to connect to NFC server
2018-11-21T22:51:53.252760+00:00 I server.go:90] [VM=myname-win10-2] Task task-7 in task set source-agent pending
2018-11-21T22:51:53.354338+00:00 I vddk.go:145] [NFC DEBUG] NfcNewAuthdConnectionEx: Setting TCP timeouts: keepIdle 60 keepIntvl 6 keepCnt 8
2018-11-21T22:51:53.358150+00:00 I vddk.go:145] [NFC DEBUG] NfcFssrvr_IOEx: Free io buffer length = 1048576
2018-11-21T22:51:53.359665+00:00 I vddk.go:145] [NFC DEBUG] NfcFssrvr_IOEx: Reading with compression 2 at offset 7940866048, for length 1048576 with flags 0x0 filetype NFC_DISK
2018-11-21T22:51:53.359999+00:00 I vddk.go:145] [NFC DEBUG] NfcFssrvr_IOEx: Allocated decompression buffer length = 1048576
2018-11-21T22:51:53.448950+00:00 I vddk.go:145] [NFC DEBUG] NfcFssrvr_IOEx: Free io buffer length = 1048576
2018-11-21T22:51:53.449201+00:00 I vddk.go:145] [NFC DEBUG] NfcFssrvr_IOEx: Reading with compression 2 at offset 7840202752, for length 1048576 with flags 0x0 filetype NFC_DISK
2018-11-21T22:51:53.449623+00:00 I vddk.go:145] [NFC DEBUG] NfcFssrvr_IOEx: Allocated decompression buffer length = 1048576
...
2018-11-21T22:51:53.464156+00:00 I vddk.go:145] NFC Sync IO session is established.
2018-11-21T22:51:53.464667+00:00 I vddk.go:145] Opening file [MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk (FASTLZ-vpxa-nfc://[MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk@xodus-qa-01.eng.mycompany.com:902!52 58 19 63 63 d6 88 92-31 4d 90 29 9f aa ec 63)
2018-11-21T22:51:53.464936+00:00 I vddk.go:145] [NFC DEBUG] NfcFssrvrClientOpen: Opening disk '[MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk' flags 32782
2018-11-21T22:51:54.464039+00:00 I vddk.go:145] [NFC DEBUG] NfcFssrvr_IOEx: Free io buffer length = 1048576
...
2018-11-21T22:51:54.993563+00:00 I vddk.go:145] [NFC DEBUG] NfcFssrvr_IOEx: Reading with compression 2 at offset 7907311616, for length 1048576 with flags 0x0 filetype NFC_DISK
2018-11-21T22:51:54.993763+00:00 I vddk.go:145] [NFC DEBUG] NfcFssrvr_IOEx: Allocated decompression buffer length = 1048576
2018-11-21T22:51:55.115839+00:00 W vddk.go:150] [NFC ERROR] NfcFssrvrProcessErrorMsg: received NFC error 13 from server: NfcFssrvrOpen: Failed to open '[MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk'
2018-11-21T22:51:55.116727+00:00 I vddk.go:145] [NFC DEBUG] NfcFssrvrClientOpen: Opening disk '[MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk' flags 32782
2018-11-21T22:51:55.117149+00:00 W vddk.go:150] [NFC ERROR] NfcFssrvrClientOpen: Received unexpected message: NFC_SESSION_COMPLETE from server. Expected message: NFC_FSSRVR_DISKGEO
2018-11-21T22:51:55.117548+00:00 I vddk.go:145] DISKLIB-DSCPTR: : "FASTLZ-vpxa-nfc://[MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk@xodus-qa-01.eng.mycompany.com:902!52 58 19 63 63 d6 88 92-31 4d 90 29 9f aa ec 63" : Failed to open NBD extent.
2018-11-21T22:51:55.117806+00:00 I vddk.go:145] DISKLIB-LINK : "FASTLZ-vpxa-nfc://[MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk@xodus-qa-01.eng.mycompany.com:902!52 58 19 63 63 d6 88 92-31 4d 90 29 9f aa ec 63" : failed to open (NBD_ERR_GENERIC).
2018-11-21T22:51:55.118143+00:00 I vddk.go:145] DISKLIB-CHAIN : "FASTLZ-vpxa-nfc://[MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk@xodus-qa-01.eng.mycompany.com:902!52 58 19 63 63 d6 88 92-31 4d 90 29 9f aa ec 63" : failed to open (NBD_ERR_GENERIC).
2018-11-21T22:51:55.118639+00:00 I vddk.go:145] DISKLIB-LIB : Failed to open 'FASTLZ-vpxa-nfc://[MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk@xodus-qa-01.eng.mycompany.com:902!52 58 19 63 63 d6 88 92-31 4d 90 29 9f aa ec 63' with flags 0x800e NBD_ERR_GENERIC (290).
2018-11-21T22:51:55.118971+00:00 I vddk.go:145] VixDiskLib: Detected DiskLib error 290 (NBD_ERR_GENERIC).
2018-11-21T22:51:55.119372+00:00 I vddk.go:145] VixDiskLib: Failed to open disk FASTLZ-vpxa-nfc://[MYCP-JAGUAR-DS-1] myname-centos-64-1/myname-centos-64-1-000172.vmdk@xodus-qa-01.eng.mycompany.com:902!52 58 19 63 63 d6 88 92-31 4d 90 29 9f aa ec 63. Error 1 (Unknown error) (DiskLib error 290: NBD_ERR_GENERIC) at 5209.