none
FSLogix logon with Cloud Cache Profiles doesn't work occasionally: AcquireExclusiveLock Access denied RRS feed

  • Question

  • I have four PoC Environments with Citrix CVAD 1912 Machine Creation Services on Windows Server 2016 Datacenter de-DE with FSLogix 1909 HF_01 2.9.7237.48865. Every few days I have users who cannot logon for 15-30 minutes where they hang in the login screen stating the message: "Please wait for FSLogix Apps Services"

    The Log "C:\ProgramData\FSLogix\Logs\CloudCacheService" states:

    [08:25:48.066][tid:00000ca0.0000246c][INFO]           ===== Begin Session:  CCache::AcquireExclusiveLock
    [08:25:48.066][tid:00000ca0.0000246c][INFO]             Acquiring exclusive CCD lock for file path: C:\ProgramData\FSLogix\Proxy\anyusername_S-1-5-21-2505351160-4269483969-3991436212-4185\Profile_anyusername.VHDX
    [08:25:48.066][tid:00000ca0.0000246c][INFO]             File Name converted to NT path name "C:\ProgramData\FSLogix\Proxy\anyusername_S-1-5-21-2505351160-4269483969-3991436212-4185\Profile_anyusername.VHDX" -> "\Device\HarddiskVolume3\ProgramData\FSLogix\Proxy\anyusername_S-1-5-21-2505351160-4269483969-3991436212-4185\Profile_anyusername.VHDX"
    [08:25:48.695][tid:00000ca0.0000246c][ERROR:00000005]   SMBStorage.cpp(809): [WCODE: 0x00000005] Unable to open/create the lock file: \\xa-wms2019-01.domain.local\profiles_ctx$\anyusername_S-1-5-21-2505351160-4269483969-3991436212-4185\Profile_anyusername.VHDX.lock (Access denied)
    [08:25:48.695][tid:00000ca0.0000246c][INFO]           ===== End Session:  CCache::AcquireExclusiveLock

    The log file: C:\ProgramData\FSLogix\Logs\CloudCacheProvider

    [08:25:49.726][tid:00000ca0.0000246c][ERROR:00000000]                           Lock file read retry count exceeded
    [08:25:49.726][tid:00000ca0.0000246c][ERROR:00000000]                           Failed to acquire a shared reader lock '\\xa-wms2019-01.amm-nbg.intra\profiles_ctx$\dangeloudis_S-1-5-21-2505351160-4269483969-3991436212-4185\Profile_anyusername.VHDX.lock': SMBStorage.cpp(809): [WCODE: 0x00000005] Unable to open/create the lock file: \\xa-wms2019-01.amm-nbg.intra\profiles_ctx$\anyusername_S-1-5-21-2505351160-4269483969-3991436212-4185\Profile_anyusername.VHDX.lock
    [08:25:49.773][tid:00000ca0.0000246c][ERROR:00000000]                           Failed to read lock file: SMBStorage.cpp(809): [WCODE: 0x00000005] Unable to open/create the lock file: \\xa-wms2019-01.amm-nbg.intra\profiles_ctx$\anyusername_S-1-5-21-2505351160-4269483969-3991436212-4185\Profile_anyusername.VHDX.lock
    [08:25:49.820][tid:00000ca0.0000246c][ERROR:00000000]                           Failed to read lock file: SMBStorage.cpp(809): [WCODE: 0x00000005] Unable to open/create the lock file: \\xa-wms2019-01.amm-nbg.intra\profiles_ctx$\anyusername_S-1-5-21-2505351160-4269483969-3991436212-4185\Profile_anyusername.VHDX.lock
    [08:25:49.851][tid:00000ca0.0000246c][ERROR:00000000]                           Failed to read lock file: SMBStorage.cpp(809): [WCODE: 0x00000005] Unable to open/create the lock file: \\xa-wms2019-01.amm-nbg.intra\profiles_ctx$\anyusername_S-1-5-21-2505351160-4269483969-3991436212-4185\Profile_anyusername.VHDX.lock
    [08:25:49.913][tid:00000ca0.0000246c][ERROR:00000000]                           Failed to read lock file: SMBStorage.cpp(809): [WCODE: 0x00000005] Unable to open/create the lock file: \\xa-wms2019-01.amm-nbg.intra\profiles_ctx$\anyusername_S-1-5-21-2505351160-4269483969-3991436212-4185\Profile_anyusername.VHDX.lock
    [08:25:49.945][tid:00000ca0.0000246c][ERROR:00000000]                           Failed to read lock file: SMBStorage.cpp(809): [WCODE: 0x00000005] Unable to open/create the lock file: \\xa-wms2019-01.amm-nbg.intra\profiles_ctx$\anyusername_S-1-5-21-2505351160-4269483969-3991436212-4185\Profile_anyusername.VHDX.lock
    [08:25:49.976][tid:00000ca0.0000246c][ERROR:00000000]                           Lock file read retry count exceeded

    In the Log file: C:\ProgramData\FSLogix\Logs\Profile

    [08:25:44.113][tid:00000ca8.000071f4][INFO]           ===== Begin Session: Logon
    [08:25:44.113][tid:00000ca8.000071f4][INFO]            User: S-1-5-21-2505351160-4269483969-3991436212-4185 (anyusername)
    [08:25:44.113][tid:00000ca8.000071f4][INFO]            Acquiring mutex for user logon
    [08:25:44.113][tid:00000ca8.000071f4][INFO]            Configuration setting not found: SOFTWARE\FSLogix\Profiles\LogonSyncMutexTimeout.  Using default: 60000
    [08:25:44.113][tid:00000ca8.000071f4][INFO]            Mutex acquired
    [08:25:44.113][tid:00000ca8.000071f4][INFO]           ===== Begin Session:  LoadProfile: anyusername
    [08:25:44.113][tid:00000ca8.000071f4][INFO]             Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\Enabled.  Data: 1
    [08:25:44.113][tid:00000ca8.000071f4][INFO]             User: anyusername. SID: S-1-5-21-2505351160-4269483969-3991436212-4185.
    [08:25:44.113][tid:00000ca8.000071f4][INFO]             Include group SID: S-1-5-21-2055974115-1815602593-4226288715-1209
    [08:25:44.113][tid:00000ca8.000071f4][INFO]             Exclude group SID: S-1-5-21-2055974115-1815602593-4226288715-1208
    [08:25:44.113][tid:00000ca8.000071f4][INFO]             User is a member of the include group
    [08:25:44.113][tid:00000ca8.000071f4][INFO]             Status set to 200: Setup in progress
    [08:25:44.113][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\RedirectType.  Using default: 2
    [08:25:44.113][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\ConcurrentUserSessions.  Using default: 1
    [08:25:44.113][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\VolumeWaitTimeMS.  Using default: 20000
    [08:25:44.113][tid:00000ca8.000071f4][INFO]             Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\DeleteLocalProfileWhenVHDShouldApply.  Data: 1
    [08:25:44.113][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\FSLogixShellPath.  Using default: 
    [08:25:44.129][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\AccessNetworkAsComputerObject.  Using default: 0
    [08:25:44.129][tid:00000ca8.000071f4][INFO]             Accessing network as user object
    [08:25:44.129][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\AttachVHDSDDL.  Using default: 
    [08:25:48.050][tid:00000ca8.000071f4][INFO]             Successfully removed Profile for S-1-5-21-2505351160-4269483969-3991436212-4185
    [08:25:48.050][tid:00000ca8.000071f4][INFO]             Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\ProfileType.  Data: 3
    [08:25:48.050][tid:00000ca8.000071f4][INFO]             Profile type: If first then Read/Write
    [08:25:48.050][tid:00000ca8.000071f4][INFO]             Configuration Read (REG_SZ): SOFTWARE\FSLogix\Profiles\CCDLocations.
    [08:25:48.050][tid:00000ca8.000071f4][INFO]             CCDLocations found - will use a Cloud Disk
    [08:25:48.050][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\DiffDiskParentFolderPath.  Using default: C:\windows\TEMP\
    [08:25:48.050][tid:00000ca8.000071f4][INFO]             Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\ClearCacheOnLogoff.  Data: 1
    [08:25:48.050][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\CCDMachineId.  Using default: WS2016-002-05.domain.local
    [08:25:48.050][tid:00000ca8.000071f4][INFO]             Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\FlipFlopProfileDirectoryName.  Data: 1
    [08:25:48.050][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\VHDNamePattern.  Using default: Profile_%username%
    [08:25:48.050][tid:00000ca8.000071f4][INFO]             Configuration Read (REG_SZ): SOFTWARE\FSLogix\Profiles\VolumeType.  Data: VHDX
    [08:25:48.050][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\VHDNameMatch.  Using default: Profile*
    [08:25:48.050][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\NoProfileContainingFolder.  Using default: 0
    [08:25:48.066][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\SIDDirSDDL.  Using default: 
    [08:25:49.085][tid:00000ca8.000071f4][INFO]             Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\LockedRetryCount.  Data: 12
    [08:25:49.085][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\LockedRetryInterval.  Using default: 

    And sometime later in the same log file: C:\ProgramData\FSLogix\Logs\Profile

    [09:04:32.198][tid:00000ca8.000071f4][INFO]             Status set to 1: Cannot load user's profile
    [09:04:32.198][tid:00000ca8.000071f4][INFO]             Error set to 33
    [09:04:32.198][tid:00000ca8.000071f4][ERROR:00000021]   D:\agent_01_work\1\s\libraries\Frx.ServiceLib\Frx.Service.VHDProfileProvider.cpp(458): Frx.Service.VHDProfileProvider.cpp(458): [WCODE: 0x00000021] Could not acquire a lock for vhd(x): C:\ProgramData\FSLogix\Proxy\anyusername_S-1-5-21-2505351160-4269483969-3991436212-4185\Profile_anyusername.VHDX (Der Prozess kann nicht auf die Datei zugreifen, da ein anderer Prozess einen Teil der Datei gesperrt hat.)
    [09:04:32.198][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\PreventLoginWithFailure.  Using default: 0
    [09:04:32.198][tid:00000ca8.000071f4][ERROR:00000021]   LoadProfile failed.  User: anyusername. SID: S-1-5-21-2505351160-4269483969-3991436212-4185. (Der Prozess kann nicht auf die Datei zugreifen, da ein anderer Prozess einen Teil der Datei gesperrt hat.)
    [09:04:32.198][tid:00000ca8.000071f4][INFO]             loadProfile time: 2328062 milliseconds
    [09:04:32.198][tid:00000ca8.000071f4][INFO]           ===== End Session:  LoadProfile: anyusername
    [09:04:32.198][tid:00000ca8.000071f4][INFO]           ===== End Session: Logon
    [09:04:32.433][tid:00000ca8.00001a44][INFO]           ===== Begin Session: Profile Directory Changed: S-1-5-21-2505351160-4269483969-3991436212-4185
    [09:04:32.433][tid:00000ca8.00001a44][INFO]            New Profile Directory: C:\Users\anyusername
    [09:04:32.433][tid:00000ca8.00001a44][INFO]            Error set to 33
    [09:04:32.433][tid:00000ca8.00001a44][INFO]           ===== End Session: Profile Directory Changed: S-1-5-21-2505351160-4269483969-3991436212-4185
    [09:04:55.638][tid:00000ca8.000071f4][INFO]           ===== Begin Session: Logoff
    [09:04:55.638][tid:00000ca8.000071f4][INFO]            User: S-1-5-21-2505351160-4269483969-3991436212-4185 (anyusername)
    [09:04:55.638][tid:00000ca8.000071f4][INFO]            Acquiring Lock for user logoff
    [09:04:55.638][tid:00000ca8.000071f4][INFO]            Configuration setting not found: SOFTWARE\FSLogix\Profiles\LogonSyncMutexTimeout.  Using default: 60000
    [09:04:55.638][tid:00000ca8.000071f4][INFO]            Mutex acquired
    [09:04:55.638][tid:00000ca8.000071f4][INFO]           ===== Begin Session:  Unload profile: anyusername
    [09:04:55.638][tid:00000ca8.000071f4][INFO]             User: anyusername. SID: S-1-5-21-2505351160-4269483969-3991436212-4185.
    [09:04:55.638][tid:00000ca8.000071f4][INFO]             Session configuration read (REG_SZ): SOFTWARE\FSLogix\Profiles\Sessions\S-1-5-21-2505351160-4269483969-3991436212-4185\ActivityId = 'e95234a5-d3f4-0000-366a-94e9f4d3d501'
    [09:04:55.638][tid:00000ca8.000071f4][INFO]             Error set to 33
    [09:04:55.638][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\ConcurrentUserSessions.  Using default: 1
    [09:04:55.638][tid:00000ca8.000071f4][INFO]             Profile refcount decremented to: -1
    [09:04:55.638][tid:00000ca8.000071f4][INFO]             No teardown required
    [09:04:55.638][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\ShutdownOnUserLogoff.  Using default: 0
    [09:04:55.638][tid:00000ca8.000071f4][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\RebootOnUserLogoff.  Using default: 0
    [09:04:55.638][tid:00000ca8.000071f4][INFO]             UnloadProfile successful.  User: anyusername. SID: S-1-5-21-2505351160-4269483969-3991436212-4185.
    [09:04:55.638][tid:00000ca8.000071f4][INFO]             unloadProfile time: 0 milliseconds
    [09:04:55.638][tid:00000ca8.000071f4][INFO]           ===== End Session:  Unload profile: anyusername
    [09:04:55.638][tid:00000ca8.000071f4][INFO]           ===== End Session: Logoff

    GPO configuration is: type=smb,connectionString=\\xa-wms2019-01.domain.local\profiles_ctx$;type=smb,connectionString=\\xa-wms2019-02.domain.local\profiles_ctx$

    Has anybody an idea how to solve this?

    Wednesday, January 29, 2020 9:03 AM

All replies

  • Hello Xeen Admin, 

    We are having the same issue here and the Log is looking exactly the same like yours.

    Did you manage to solve the problem, it will be really helpful.

    Regards,

    Zaidan 

    Thursday, February 27, 2020 3:41 PM
  • Hi Zaidan, no the problem was not solved. It still occurs sometimes and I have a case open with MS that leads nowhere. MS insists on Anti Virus being the problem and they encourage us to test without Anti Virus installed.
    Monday, March 2, 2020 10:56 AM
  • Disable AntiVirus on the Citrix server or on the File Servers ?
    Monday, March 2, 2020 4:11 PM
  • Hello Everyone, 

    Thanks alot for the Tipp, I will disable the Anti-Virus and let you know wheather the problem is solved. 



    Best Regards,

    Zaidan

    Tuesday, March 3, 2020 1:21 PM
  • Hello Everyone,

    Sorry for the late Answer. 

    after checking the FileServer i came up to this Conclusion:

    Missleading was that, we dont have an Antivirus installed on the Server so i didn't deactivate anything, but, on the FSLogix Service Server we have one, therefore, we have "execluded" the "FSLogix" Service from the Antivirus. This was the first solution we did, also, in the Group Policies we have deactivated the "Clear local cache on logoff".

    Since then we didnt have any problems. Hope that helps the others.

    regards,

    Zaidan


    Tuesday, March 10, 2020 9:06 AM
  • We also don't have Anti Virus on BOTH SMB Fileservers (Cloud Cache).

    On the Citrix VDA Worker, we have the following exclusions in place, since day one:
    C:\Program Files\FSLogix\*
    C:\ProgramData\FSLogix\*

    I think your suggestion with deactivating "Clear local cache on logoff" is quite interesting. We have that enabled. How did you think of that setting?

    Tuesday, March 10, 2020 9:31 AM
  • We are now much further with our testings. We have deployed MCS clones without ESET AntiVirus, and still Cloud Cache logins will fail after a few days.
    Has anybody new informations? It's still the same error as before. WS2016 with latest FSLogix 2.9.7237.48865
    Thursday, March 19, 2020 2:04 PM
  • We are having this issue randomly.

    I have disable Windows Defender on Citrix Servers by GPO and we have exclude VHD, VHDX, LOCK, META files types in Defender on Scale-Out Files Servers.

    The problem is still there.

    Friday, March 27, 2020 5:59 PM
  • I still have the issue with Public Preview: FSLogix Apps release 2004 (2.9.7349.30108)

    Logs have been improved in the new version.

    I have opened a new incident with Microsoft

    Friday, April 3, 2020 8:08 PM
  • We had the same problem in a W2016 environment after testing without the anti virus we don't see these lock problems anymore. This occurs often under heavy load on the machine.
    Thursday, April 16, 2020 8:29 AM
  • Hello Xen,

    Just an Update for the Issue: we are still getting the same problem and it happens randomly, it goes away for 2 weeks and comes back afterwards.

    somehow the problem is now as following: we dont get the FSLogic Service error, but sometimes the users are getting a black Screen when they try to Login, and then after they close the RDS Window and try to Login again they get the error that the Service is Overloaded and they should try to login later. 

    We have checked nearly everything on the Servers, they have always more than enough RAM and CPU left even when everyone is logged in and activly working.

    Did you manage to get it running one Month with no errors ? 

    regards,

    Zaidan


    Wednesday, July 1, 2020 8:37 AM