none
Locked VHD(X) file, issues when logging in RRS feed

  • Question

  • Running into issues with a WVD environment consisting of 1 host pool and 2 Windows 10 Multi-Session host. Sometimes the users are unable to login, the FSLogix logs shows that the VHDX file is locked by another process (Error near the end). Only 5 users log on to a oversized host (64GB, 14vCPU, 256 Premium SSD). The sizing can't be the issue, but how do i determine which file/process is responsible for locking the VHDX? (the server was rebooted before the users started to login, so there were no disconnected sessions). Also, the latest FSLogix agent 1909 was installed on both servers.

     

    [09:01:18.407][tid:00000f34.00002bf8][INFO] ===== Begin Session: Logon
    [09:01:18.407][tid:00000f34.00002bf8][INFO] User: S-1-5-21-687924372-4293999746-2831884817-1299 (Testuser)
    [09:01:18.407][tid:00000f34.00002bf8][INFO] Acquiring mutex for user logon
    [09:01:18.408][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\LogonSyncMutexTimeout. Using default: 60000
    [09:01:18.408][tid:00000f34.00002bf8][INFO] Mutex acquired
    [09:01:18.408][tid:00000f34.00002bf8][INFO] ===== Begin Session: LoadProfile: Testuser
    [09:01:18.408][tid:00000f34.00002bf8][INFO] Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\Enabled. Data: 1
    [09:01:18.408][tid:00000f34.00002bf8][INFO] User: Testuser. SID: S-1-5-21-687924372-4293999746-2831884817-1299.
    [09:01:18.409][tid:00000f34.00002bf8][INFO] Include group SID: S-1-5-21-3446287254-2035122344-4217171115-1001
    [09:01:18.409][tid:00000f34.00002bf8][INFO] Exclude group SID: S-1-5-21-3446287254-2035122344-4217171115-1000
    [09:01:18.409][tid:00000f34.00002bf8][INFO] User is a member of the include group
    [09:01:18.409][tid:00000f34.00002bf8][INFO] Status set to 200: Setup in progress
    [09:01:18.409][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\RedirectType. Using default: 2
    [09:01:18.409][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\ConcurrentUserSessions. Using default: 1
    [09:01:18.410][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\VolumeWaitTimeMS. Using default: 20000
    [09:01:18.410][tid:00000f34.00002bf8][INFO] Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\DeleteLocalProfileWhenVHDShouldApply. Data: 1
    [09:01:18.410][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\FSLogixShellPath. Using default:
    [09:01:18.410][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\AccessNetworkAsComputerObject. Using default: 0
    [09:01:18.410][tid:00000f34.00002bf8][INFO] Accessing network as user object
    [09:01:18.410][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\AttachVHDSDDL. Using default:
    [09:01:18.411][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\ProfileType. Using default: 0
    [09:01:18.411][tid:00000f34.00002bf8][INFO] Profile type: Normal
    [09:01:18.411][tid:00000f34.00002bf8][INFO] Configuration Read (REG_SZ): SOFTWARE\FSLogix\Profiles\CCDLocations.
    [09:01:18.412][tid:00000f34.00002bf8][INFO] CCDLocations found - will use a Cloud Disk
    [09:01:18.412][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\DiffDiskParentFolderPath. Using default: C:\WINDOWS\TEMP\
    [09:01:18.413][tid:00000f34.00002bf8][INFO] Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\ClearCacheOnLogoff. Data: 1
    [09:01:18.413][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\CCDMachineId. Using default: WVD-01.Organization.local
    [09:01:18.413][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\FlipFlopProfileDirectoryName. Using default: 0
    [09:01:18.413][tid:00000f34.00002bf8][INFO] Configuration Read (REG_SZ): SOFTWARE\FSLogix\Profiles\SIDDirNamePattern. Data: %userdomain%-%username%
    [09:01:18.413][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\VHDNamePattern. Using default: Profile_%username%
    [09:01:18.414][tid:00000f34.00002bf8][INFO] Configuration Read (REG_SZ): SOFTWARE\FSLogix\Profiles\VolumeType. Data: VHDX
    [09:01:18.414][tid:00000f34.00002bf8][INFO] Configuration Read (REG_SZ): SOFTWARE\FSLogix\Profiles\SIDDirNameMatch. Data: %userdomain%-%username%
    [09:01:18.414][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\VHDNameMatch. Using default: Profile*
    [09:01:18.418][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\NoProfileContainingFolder. Using default: 0
    [09:01:18.456][tid:00000f34.00002bf8][INFO] Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\LockedRetryCount. Data: 1
    [09:01:18.456][tid:00000f34.00002bf8][INFO] Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\LockedRetryInterval. Data: 0
    [09:01:18.460][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\SIDDirSDDL. Using default:
    [09:01:18.497][tid:00000f34.00002bf8][INFO] Status set to 1: Cannot load user's profile
    [09:01:18.497][tid:00000f34.00002bf8][INFO] Error set to 33
    [09:01:18.498][tid:00000f34.00002bf8][ERROR:00000021] D:\agent_01_work\2\s\libraries\Frx.ServiceLib\Frx.Service.VHDProfileProvider.cpp(452): Frx.Service.VHDProfileProvider.cpp(452): [WCODE: 0x00000021] Could not acquire an exclusive lock for vhd(x): C:\ProgramData\FSLogix\Proxy\Organization-Testuser\Profile_Testuser.VHDX (The process cannot access the file because another process has locked a portion of the file.)
    [09:01:18.498][tid:00000f34.00002bf8][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\PreventLoginWithFailure. Using default: 0
    [09:01:18.500][tid:00000f34.00002bf8][ERROR:00000021] LoadProfile failed. User: Testuser. SID: S-1-5-21-687924372-4293999746-2831884817-1299. (The process cannot access the file because another process has locked a portion of the file.)
    [09:01:18.500][tid:00000f34.00002bf8][INFO] loadProfile time: 93 milliseconds
    [09:01:18.500][tid:00000f34.00002bf8][INFO] ===== End Session: LoadProfile: Testuser


    Wednesday, October 2, 2019 8:46 PM

All replies

  • @Marc-1983, When you are using cloud cache, the system is trying to perform locking across all the storage locations. What it's doing is creating a file in the location where the VHD gets stored that indicates the VHD is locked by another system. This file is named the same as your VHD file with a .lock extension. There should be some more information in your cloud cache logs related to this.

    The lock file contains some information about which machine is holding the lock, and when they last updated that they were doing so. It's not really a human readable format file, but I think you could type it and see what computer names it has in it. It seems likely that during testing maybe users are not logging out successfully so these lock files don't get cleaned up.

    If you know the file is not in use, you can safely delete the lock file.

    Tuesday, October 8, 2019 3:47 PM
    Moderator
  • I'm having a similar issue - was not using Cloud Cache and I thought maybe there is something misconfigured that was causing it to think I was using it.  So I configured it to use cloud cache and I'm still getting the same errors above.  I can't find much else about it.

    Are there any other suggestions?
    Wednesday, November 20, 2019 5:17 PM
  • I'm having a similar issue - was not using Cloud Cache and I thought maybe there is something misconfigured that was causing it to think I was using it.  So I configured it to use cloud cache and I'm still getting the same errors above.  I can't find much else about it.

    Are there any other suggestions?

    Are you also in WVD? The most common cause of this in WVD is a user (usually an admin) connecting directly to one of the hosts using RDP for some maintenance task but not through the WVD broker.  The WVD broker will point you to an already existing session if it is aware of it, but on a direct connection not through WVD the session is not known to the WVD broker, and so it may route you on your connection to a new host, and your VHD is still locked by the one from the sessions created outside of the WVD service.  What type of Profile storage are you using?  In many cases you can connect to the file server and see what the open file handles are to a file on that storage.  That would let you know which host has the VHD locked.  If you have a disconnected (but still existing) session for a user on a host this will hold on to the VHD.

    If you are not running in WVD what broker are you using?  Does your scenario allow users to have sessions on multiple hosts simultaneously?

    • Edited by Brian Mann1 Wednesday, November 20, 2019 7:06 PM
    Wednesday, November 20, 2019 7:04 PM
  • Did anyone find a resolution on this?  We're building out a new server 2016 Citrix environment using FSLogix profile containers.  What we're seeing is in the first session the profile loads fine, but if you try to open another session on a different server it fails with:

    [10:00:13.574][tid:00000e40.000012f8][INFO]             Status set to 1: Cannot load user's profile
    [10:00:13.574][tid:00000e40.000012f8][INFO]             Error set to 33
    [10:00:13.574][tid:00000e40.000012f8][ERROR:00000021]   c:\agent_02\_work\3\s\libraries\frx.servicelib\frx.service.vhdprofileprovider.cpp(449): frx.service.vhdprofileprovider.cpp(449): [WCODE: 0x00000021] Cloud not acquire an exclusive lock for vhd(x): C:\ProgramData\FSLogix\Proxy\Win2K16\Profile_TestVHDX (The process cannot access the file because another process has locked a portion of the file.

     

    We do have the policies to allow concurrent sessions and multiple connections which should allow for loading the VHDx on multiple servers at once.  

    Wednesday, December 18, 2019 4:30 PM
  • Did anyone find a resolution on this?  We're building out a new server 2016 Citrix environment using FSLogix profile containers.  What we're seeing is in the first session the profile loads fine, but if you try to open another session on a different server it fails with:

    [10:00:13.574][tid:00000e40.000012f8][INFO]             Status set to 1: Cannot load user's profile
    [10:00:13.574][tid:00000e40.000012f8][INFO]             Error set to 33
    [10:00:13.574][tid:00000e40.000012f8][ERROR:00000021]   c:\agent_02\_work\3\s\libraries\frx.servicelib\frx.service.vhdprofileprovider.cpp(449): frx.service.vhdprofileprovider.cpp(449): [WCODE: 0x00000021] Cloud not acquire an exclusive lock for vhd(x): C:\ProgramData\FSLogix\Proxy\Win2K16\Profile_TestVHDX (The process cannot access the file because another process has locked a portion of the file.

     

    We do have the policies to allow concurrent sessions and multiple connections which should allow for loading the VHDx on multiple servers at once.  

    Can you share what settings you have set to allow the connection from multipl servers?  

    ConcurrentUserSessions will allow concurrent sessions on the same server only.

    ProfileType is the setting that you will need to use to allow connections from multiple servers.  See https://docs.microsoft.com/en-us/fslogix/profile-container-configuration-reference for full details.

    If you already are using that and you are still seeing this we may need to have you open a support ticket so that we can see the full logs that you probably do not want to share here.

    Saturday, December 21, 2019 12:44 AM
  • Hi Brian,

    thanks for the reply. I've changed the profile type to RW with fallback to Read only.  It seems to be working now, but intermittently still having issues with locked RW file etc.  Seeing various errors in the FSLogix event logs: 

    Event 26 Cannot get Token from SID.  

    Event 26 Load Profile failed Access is denied

    register failed for path "C:\programdata\FSLogix\Proxy\Win2K16\RW.VHDX (access is denied) 

    Lock file read retry count exceeded

    Failed to read lock file, unable to open/create lock file: \\fileserver\container\username\user\rw.vhdx.lock

    have you seen anything like this?  


    Monday, December 23, 2019 6:08 PM
  • Hi Brian,

    thanks for the reply. I've changed the profile type to RW with fallback to Read only.  It seems to be working now, but intermittently still having issues with locked RW file etc.  Seeing various errors in the FSLogix event logs: 

    Event 26 Cannot get Token from SID.  

    Event 26 Load Profile failed Access is denied

    register failed for path "C:\programdata\FSLogix\Proxy\Win2K16\RW.VHDX (access is denied) 

    Lock file read retry count exceeded

    Failed to read lock file, unable to open/create lock file: \\fileserver\container\username\user\rw.vhdx.lock

    have you seen anything like this?  


    Event 26 Cannot get Token from SID. is a benign error, and will be removed in a future release.  It is expected in many cases.

    The other errors sound like filesystem permission issues.  It is not clear to me from what you have shared here whether they are permission problems on the local filesystem, or on an SMB share.  But in the case of a failure to retry the lock aquisition up to the retry limit Lock file read retry count exceeded is what I would expect to see.  We will just need to figure out why you do not have access to read/create the lock files, then it looks like things should work for you.  What build of the product are you on?

    Monday, December 23, 2019 8:13 PM
  • We are running 2.9.7117.27413
    Tuesday, December 24, 2019 6:41 PM
  • looking at the lock file on the network share it says the owner is "administrators".  all other files in the profile have the user as the owner.  
    Tuesday, December 24, 2019 7:13 PM
  • I think I have this resolved now.  I changed the profile type back to "try RW with fallback to RO".  I was still seeing profile locks on the 2nd session in the logs.  

    I was reading through the forums and somebody said the machine account might need full control to the profile container for logging.  So I granted Domain Computers full control to the container and now the lock file errors are gone.  I'm not sure if this was the fix since the documentation doesn't say anything about computer accounts needing access to the profile, but things seem to be working now.  

    I can launch a Xenapp desktop, then launch a published app on a different xenapp server and it launches fine and profile is loading without lock errors.. 

    • Proposed as answer by GlennD88 Wednesday, April 1, 2020 6:02 PM
    Thursday, December 26, 2019 6:10 PM
  • I think I have this resolved now.  I changed the profile type back to "try RW with fallback to RO".  I was still seeing profile locks on the 2nd session in the logs.  

    I was reading through the forums and somebody said the machine account might need full control to the profile container for logging.  So I granted Domain Computers full control to the container and now the lock file errors are gone.  I'm not sure if this was the fix since the documentation doesn't say anything about computer accounts needing access to the profile, but things seem to be working now.  

    I can launch a Xenapp desktop, then launch a published app on a different xenapp server and it launches fine and profile is loading without lock errors.. 

    Thank you for this detailed information.  I am glad this is working for you. This could be a bug in our locking code.  Our intent would be that the computer object would not need this access.  I will log an internal bug for us to investigate this internally in a future release.
    Friday, January 3, 2020 8:58 PM
  • Is there any solutions for this? Do we need to give domain computers privileges on all user folders where containers resides?

    Dragan Penkov MCSA,VCP

    Wednesday, January 29, 2020 9:04 AM
  • We experienced the same issue on a Xenapp farm with windows 2012r2 servers.

    I granted full control access rights to the computer accounts of the xenapp farm as proposed by Ron Decker Duluth and the problem seems to be resolved. I do need to tes further but seems to be looking good for now...

    Thanks Ron for sharing this information...

    Could this be a bug with fslogix in combination with 2012r2 as I haven't experienced this on other operating systems yet...

    Wednesday, April 1, 2020 6:07 PM