Writable Volume Times Out When Loading

[CPludie]

Hello folks!  Long time lurker first time poster, hoping to get some help from this fine community.

I'm having an issue attaching a writable volume using AppVolumes 4.  I've just stood this up so I don't have any AppStacks to test yet but I assume that would fail to mount as well.

I do see the volume as Attached in the management console, the disk is present in vSphere under the VM's hardware as Hard Disk 2 and I do see C:\SnapVolumesTemp\MountPoints\{id}.  Looking at the svservice log I see errors on failing to open meta.yml, harddiskvolume is readonly etc.  The service will wait the 180 seconds and ultimately time out - [2020-03-05 13:18:06.620 UTC] [svservice:P1792:T292] RunExecutableAsUser: CommandLine svservice.exe message "Timed out when loading assigned volumes, please retry or contact your administrator."

Notable error entries from log -

[2020-03-05 13:15:06.703 UTC] [svservice:P1792:T2028] SetMetaVolGUIDInternal: file \\?\GLOBALROOT\Device\HarddiskVolume3\METADATA\_meta.yml cannot be opened for write, error 13!

[2020-03-05 13:15:06.704 UTC] [svservice:P1792:T2028] SetMetaVolGUID("{fafba04f-8558-4662-b2e8-01379e6875de}") to ("\\?\GLOBALROOT\Device\HarddiskVolume3\METADATA\_meta.yml") error!

[2020-03-05 13:15:06.708 UTC] [svservice:P1792:T2028] LoadVolumeMeta: FindFirstFile(\SnapVolumesTemp\MountPoints\{2929df5c-0000-0000-0000-100000000000}\{*}) failed - 2

[2020-03-05 13:15:06.880 UTC] [svservice:P1792:T2028] svs_write_list_to_file: meta file "\SnapVolumesTemp\MountPoints\{2929df5c-0000-0000-0000-100000000000}\METADATA\_vminfo.txt" was not opened, error:13!

[2020-03-05 13:15:06.880 UTC] [svservice:P1792:T2028] RecordVMInfoIntoVolume: vm info file "\SnapVolumesTemp\MountPoints\{2929df5c-0000-0000-0000-100000000000}\METADATA\_vminfo.txt" error!

[2020-03-05 13:15:07.027 UTC] [svservice:P1792:T2028] RunScript_VolumeScripts: Failed to get old script path. Event: [logon], Volume Path: [\SnapVolumesTemp\MountPoints\{2929DF5C-0000-0000-0000-100000000000}\], warning!

[2020-03-05 13:15:07.028 UTC] [svservice:P1792:T2028] RetrieveAndApplyNetworkShareInfo: Entered

[2020-03-05 13:15:07.028 UTC] [svservice:P1792:T2028] RetrieveAndApplyNetworkShareInfo: Failed to open share info config file

[2020-03-05 13:15:07.028 UTC] [svservice:P1792:T2028] CVolumeResourceHandler::SignalBaseDiskReady: Couldn't open wemcapture_basediskready event. The system cannot find the file specified (2/00000002)

[2020-03-05 13:15:07.198 UTC] [svservice:P1792:T292] Waiting for 1 new volumes (0 processed, waited 1 second(s) so far, max wait of 180)

[2020-03-05 13:15:07.568 UTC] [svservice:P1792:T1920] WinHttpSendRequestWithSSLCertValidation: WinHttpSendRequest succeeded.

[2020-03-05 13:15:07.568 UTC] [svservice:P1792:T1920] HttpReadAllAvailableData: Error 0 in WinHttpQueryDataAvailable: dwSize 0

[2020-03-05 13:15:07.575 UTC] [svservice:P1792:T1920] CFilterDriverCommunicator::SendMessageW: FilterSendMessage() failed - 0x80070013.

[2020-03-05 13:15:07.575 UTC] [svservice:P1792:T1920] CSVDriverCommunicator::SvdAppNotification: SendMessage() failed : The media is write protected (-2147024877/80070013).

[2020-03-05 13:15:07.575 UTC] [svservice:P1792:T1920] CApplication::NotifyAppEvent: CSVDriverCommunicator::SvdAppNotification() failed. [0][1][{fafba04f-8558-4662-b2e8-01379e6875de}][{fafba04f-8558-4662-b2e8-01379e6875de}][][][1].

[2020-03-05 13:15:07.575 UTC] [svservice:P1792:T1920] CApplication::EnableApp: CApplication::NotifyAppEvent(1-Load) failed.

[2020-03-05 13:15:07.575 UTC] [svservice:P1792:T1920] CAppManager::EnableOrDisableApp: CApplication::EnableApp() failed.

[2020-03-05 13:15:07.575 UTC] [svservice:P1792:T1920] CAppManager::StartApp: EnableOrDisableApp(.0x80004005.) failed for Enable App - App ID ({fafba04f-8558-4662-b2e8-01379e6875de}) on Volume ({fafba04f-8558-4662-b2e8-01379e6875de}) for Session (1). Base App ID () on Volume (). The mount might not have been ready.

[2020-03-05 13:15:07.575 UTC] [svservice:P1792:T1920] Refreshing desktop (hToken FFFFFFFFFFFFFFFF)

[2020-03-05 13:15:07.625 UTC] [svservice:P1792:T1920] RunExecutableAsUser: Path "C:\Program Files (x86)\CloudVolumes\Agent\svservice.exe"

[2020-03-05 13:15:07.625 UTC] [svservice:P1792:T1920] RunExecutableAsUser: CommandLine svservice.exe refresh

[2020-03-05 13:15:07.628 UTC] [svservice:P1792:T1920] RunExecutableAsUser failed: no session available

[2020-03-05 13:15:07.628 UTC] [svservice:P1792:T1920] SetRegConfigDWord(VolReady, 1) success

[2020-03-05 13:15:07.628 UTC] [svservice:P1792:T1920] CVolumeResourceHandler::OnLastVolumeMount [{2929DF5C-0000-0000-0000-100000000000}]-[\Device\HarddiskVolume3]

[2020-03-05 13:15:07.629 UTC] [svservice:P1792:T1920] Creating mount point at "\SnapVolumesTemp\MountPoints\{2929DF5C-0000-0000-0000-100000000000}\"

[2020-03-05 13:15:07.631 UTC] [svservice:P1792:T1920] RunScriptParams::getOldScriptPath: Scripts for event [allvolattached] are not found for [\Device\HarddiskVolume3]: [The system cannot find the file specified (2/00000002)]

[2020-03-05 13:15:07.631 UTC] [svservice:P1792:T1920] RunScript_VolumeScripts: Failed to get old script path. Event: [allvolattached], Volume Path: [\SnapVolumesTemp\MountPoints\{2929DF5C-0000-0000-0000-100000000000}\], warning!

[2020-03-05 13:18:06.620 UTC] [svservice:P1792:T292] Waiting for 0 new volumes (1 processed, waited 180 second(s) so far, max wait of 180)

[2020-03-05 13:18:06.620 UTC] [svservice:P1792:T292] Gave up waiting for 0 remaining volume(s) to load after 180 second(s) (called by WaitVolumesLoading)

[2020-03-05 13:18:06.620 UTC] [svservice:P1792:T292] Message: "Timed out when loading assigned volumes, please retry or contact your administrator." (hToken FFFFFFFFFFFFFFFF)

[2020-03-05 13:18:06.620 UTC] [svservice:P1792:T292] RunExecutableAsUser: Path "C:\Program Files (x86)\CloudVolumes\Agent\svservice.exe"

[2020-03-05 13:18:06.620 UTC] [svservice:P1792:T292] RunExecutableAsUser: CommandLine svservice.exe message "Timed out when loading assigned volumes, please retry or contact your administrator."

[2020-03-05 13:18:06.622 UTC] [svservice:P1792:T292] RunExecutableAsUser failed: no session available

[2020-03-05 13:18:06.622 UTC] [svservice:P1792:T292] Initializing HTTP connection

[2020-03-05 13:18:06.622 UTC] [svservice:P1792:T292] Choosing a manager out of 1 configured manager(s)

[2020-03-05 13:18:06.624 UTC] [svservice:P1792:T292] HttpReportErrorMessage: agent-message URL: /agent-message?name=svservice&status=0&uuid=422668ef-6556-8fec-6600-a41bce3670dc&osver=10.0.17763&sp=0.0&suite=256&product=1&arch=9&proc=2&agentver=4.0.0.99R&domain=

[2020-03-05 13:18:06.624 UTC] [svservice:P1792:T292] [0] Connecting to 10.0.236.169:443 using HTTPS (attempt 1)

[2020-03-05 13:18:06.624 UTC] [svservice:P1792:T292] WinHttpSendRequestWithSSLCertValidation: SSL certificate validation is disabled.

[2020-03-05 13:18:06.945 UTC] [svservice:P1792:T292] WinHttpSendRequestWithSSLCertValidation: WinHttpSendRequest succeeded.

[2020-03-05 13:18:06.945 UTC] [svservice:P1792:T292] Manager status 200

[2020-03-05 13:18:06.945 UTC] [svservice:P1792:T292] HttpReportErrorMessage: succeeded

[2020-03-05 13:18:06.945 UTC] [svservice:P1792:T292] HttpUserLogin: succeeded (user login)

[2020-03-05 13:18:06.945 UTC] [svservice:P1792:T292] OnLogon: succeeded

[2020-03-05 13:18:42.744 UTC] [svservice:P1792:T1904] OnStartShell called (Session ID 1, Handle 0000024D3D904760, Params 000000C786BFEC78, Context 0000000000000000)

[2020-03-05 13:18:42.744 UTC] [svservice:P1792:T1904] OnStartShell: BERKSHIRE\cplude (NameSamCompatible)

[2020-03-05 13:18:42.744 UTC] [svservice:P1792:T1904] ExpandEnvironmentVariable: ExpandEnvironmentVariable  : %localappdata% 

[2020-03-05 13:18:42.748 UTC] [svservice:P1792:T1904] ExpandEnvironmentVariable: ExpandEnvironmentVariable  Success : C:\Users\cplude\AppData\Local 

[2020-03-05 13:18:42.748 UTC] [svservice:P1792:T1904] ExpandEnvironmentVariable: ExpandEnvironmentVariable  Returning  : C:\Users\cplude\AppData\Local 

[2020-03-05 13:18:42.819 UTC] [svservice:P1792:T1904] Creating mount point at "\SnapVolumesTemp\MountPoints\{2929DF5C-0000-0000-0000-100000000000}\"

[2020-03-05 13:18:42.820 UTC] [svservice:P1792:T1904] Checking for appcapture on "\Device\HarddiskVolume3" (event appcapture)

[2020-03-05 13:18:42.820 UTC] [svservice:P1792:T1904] RunScript_AppCaptureProgram: creating thread to check provisioning state (Event appcapture) on "\SnapVolumesTemp\MountPoints\{2929DF5C-0000-0000-0000-100000000000}\" Go Process.

[2020-03-05 13:18:42.821 UTC] [svservice:P1792:T1904] OnStartShell: Starting  ExportTileLayout Thread

[2020-03-05 13:18:42.821 UTC] [svservice:P1792:T1904] OnStartShell: ExportTileLayout Thread Created Successfully!

[2020-03-05 13:18:42.890 UTC] [svservice:P1792:T5716] MountSnapVolumeByPath: Checking for the presence of [\\?\Volume{2929df5c-0000-0000-0000-100000000000}\appcapture.exe]

[2020-03-05 13:19:26.752 UTC] [svservice:P1792:T416] Failed to open key \MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion\Run: 161

[2020-03-05 13:19:26.752 UTC] [svservice:P1792:T416] Failed to open key \MACHINE\SOFTWARE\Wow6432Node\Microsoft\Windows\CurrentVersion\Run: 161

[2020-03-05 13:23:42.893 UTC] [svservice:P1792:T4100] ExportTileLayoutThreadProc: ExportTileLayoutThreadProc:: Launching RunScript_ExportUserTileLayout .

In Device Manager there is a Warning on the SnapVolume under portable devices as well.

Current setup is

Horizon 7.11.0 build-15231595

vSphere 6.5.0.20000

AppVolumes 4.0.0.105

Thanks in advance for any ideas on what I've configured incorrectly, or overlooked.

Chris

[sjesse]

What version of windows? Also open an SR if you haven't, could be a bug. I'd delete the writeable and try it again. If you

have the same agent as the manager version

installed the agent last on the parent image

using a supported windows os

don't have any other appstacks attached

I would say something isn't working right and there isn't much we can do unless someone else has seen it.

[CPludie]

Windows is 1809 LTSC.  I originally chose version 4 to try be ahead of the curve but it may be too early in the life cycle to jump on.  I'm going to downgrade to 2.18.1 and see if I have the same issue.  I appreciate the quick reply!  What a great bunch here.

Thanks,

Chris

[Ray_handels]

Looking at the svservice log I see errors on failing to open meta.yml, harddiskvolume is readonly etc.

This tingles my spidy scense (or soemthing like that ).

If you hava a writable volume and it says that the volume is readonly it seems that when the template is copied it could well be that it added the dd.deletable=false key. Do you happen to have access to the esx host? And can you check the content of de writable volumes VMDK file (so NOT the Flat file). If this is indeed the case they made a mistake with how the writable is being copied...

[VirtualSpence]

The fact that it's showing in device mgr as a portable device seems odd.

Is the drive attaching properly in vSphere?

What about under disk management?

What type of VM is this? (Full clone, Linked clone, Instant clone)

Which UWV template did you choose when you created the volume?

[CPludie]

I apologize for the delay.  I rolled the manager and agent back to 2.18.1 to see if it was a bug with version 4, unfortunately I'm still receiving the "Timed out when loading assigned volumes, please retry or contact your administrator." message.

I do see the Writable disk in vSphere and it also shows in Disk Management as the CVWritable and shows as attached in the AppVol management console.  It's very strange that the volume appears to be attached correctly but is timing out.

I am using Instant Clones and the template selected is uia_only.

Apparently my permissions to open a tickets with VMware are a bit messed up right now so I'm working with our account rep to get that resolved(we recently had a merger).  I will be opening a ticket as soon as I'm able to.

Thanks,

Chris

[CPludie]

I have access to the datastore this is on, we're using vSan.  Would I just attach the VMDK to a VM to check the contents?  Sorry for the noob question here, I don't have much experience with AppVolumes.

Thanks,

Chris

[CPludie · Accepted solution]

Finally got support with VMware sorted out and was able to open a ticket.  You were correct on the template becoming corrupt during setup.  Apparently this situation is rare but has been observed by VMware.  From what I was told, the template import during the initial Manager setup can be incomplete but appears as though it went through fine.  Easy fix.

From the Management Console.  Configuration-->Storage-->Upload Prepackaged Volumes-->Select the template(or all templates)-->Upload.  This will replace what's currently on the datastore.

I successfully attached a writable volume to my profile!  Now time to test.

I appreciate all the feedback.  Hopefully this can help someone in the future.

Thanks,

Chris