Caution: FSLogix 2009 (2.9.7621.30127) profiles won't logoff completely

Update January 11, 2021: I was informed about a better solution via Twitter, and updated the Blog post accordingly.

The Problem

During my personal tests with FSLogix 2009 (2.9.7621.30127) I discovered that the profiles won’t logoff completely at the end of the day. See the following screenshots.

Hanging profiles (1)

Hanging profiles (2)

You can clearly see, that despite there are no active or disconnected user sessions, some of the VHDX disks are still mounted, but more important the folders from C:\users\ won’t vanish.

This makes a second login impossible on the same VDA.

The situation

At my Citrix Machine creation services (MCS) customers, I never update machine catalogs, I always replace them with fresh Golden master images installed from scratch via Microsoft Deployment Toolkit (MDT). So all tests were performed on a freshly installed machine catalog. No in-place upgrade of the FSLogix apps or the Citrix VDA. This is the affected test environment:

Windows Server 2016 de-DE
(December 8, 2020—KB4593226 (OS Build 14393.4104))
Citrix VDA 1912 CU2 via MCS
FSLogix 2009 (2.9.7621.30127)
(Single SMB share, no Cloud Cache)

Every second day, the test users were unable to login. A reboot could solve the problem temporary.

I wasn’t able to find anything meaningful in the FSLogix logs, but I post them non the less at the end of the blog post, so someone with the same issue might be able to find this blog post through his favorite search engine.

The (old) solution

The solution to my problem, after lots of different tests, was to downgrade to FSLogix 2004 (2.9.7349.30108) and all problems were instantly gone. The current test (and soon to be productive) environments for all my customers look like this now:

Windows Server 2016 de-DE
(December 8, 2020—KB4593226 (OS Build 14393.4104))
Citrix VDA 1912 CU2 via MCS
FSLogix 2004 (2.9.7349.30108)
(Single SMB share, no Cloud Cache)

The better solution

This paragraph was added on 11.01.2021

Soon after I published this blog post, Fredrik Endresen contacted my on Twitter, with the following statement:

@fslogix now uses the SID of the local includeexclude groups. So if the GPO is set up to "replace" instead of "update", it will stop working after a gpupdate within users session. This because the local groups get recreated and get new SIDs. VHDX will then not detach at logoff.

— Fredrik Endresen (@endresenfredrik) December 16, 2020

He encountered the same problems as we did, and during his troubleshooting he discovered an undocumented FSLogix change in version 2009 (2.9.7621.30127). According to him, FSLogix uses the SID of the local include/exclude groups now, instead of the name. As I manage those groups via Group Policy Preferences (GPP) and choose the mode replace instead of update, these groups get re-created during the Group Policy background refresh, which changes the SID, resulting in the issues described above.

Kudos to you. I just checked all three affected environments and the GGP is set to "replace".
So in your opinion, I would need to change the GPP to "update" and should try out the new "CleanupInvalidSessions" registry key.

— Marco Hofmann (CTA) (@xenadmin) December 16, 2020

Now the real solution would be, to double check how you manage the local FSLogix groups. If you don’t manage them via GPP, there is a great change you belong to the group of people, not affected by this problem.
Now I will test this theory during the next Citrix MCS Master Image tests, set my GPP to update instead of replace, and also as mentioned in the comments and in the World of EUC Slack, the new registry value CleanupInvalidSessions.

The FSlogix logs

FSL1.txt

[07:11:34.447][tid:00000ea0.00000ea4][INFO]            Max retries reached.  Giving up re-attach attempts.
[07:11:34.447][tid:00000ea0.00000ea4][ERROR:c03a000e]  OpenVirtualDisk (The virtual disk chain is damaged. The identifier of the parent virtual disk and the identifier of the differing disk conflict.)
[07:11:34.447][tid:00000ea0.00000ea4][INFO]           ===== End Session: Volume re-attach
[07:11:34.447][tid:00000ea0.00000ea4][INFO]           Configuration setting not found: SOFTWARE\FSLogix\Profiles\ReAttachRetryCount.  Using default: 60
[07:11:34.447][tid:00000ea0.00000ea4][INFO]           Configuration setting not found: SOFTWARE\FSLogix\Profiles\ReAttachIntervalSeconds.  Using default: 10
[07:11:34.447][tid:00000ea0.00000ea4][INFO]           ===== Begin Session: Volume re-attach
[07:11:34.447][tid:00000ea0.00000ea4][INFO]            Attempting re-attach of volume: \\?\Volume{f9af2c8e-7617-4e92-a2a9-71d301a2e7b6}\ for SID: S-1-5-21-3307134969-3200570010-XXX-2393
[07:11:34.447][tid:00000ea0.00000ea4][INFO]            Configuration setting not found: SOFTWARE\FSLogix\Profiles\LogonSyncMutexTimeout.  Using default: 60000
[07:11:34.447][tid:00000ea0.00000ea4][INFO]            Acquired reattach virtual disk lock for user S-1-5-21-3307134969-3200570010-XXX-2393 (Elapsed time: 0)
[07:11:34.447][tid:00000ea0.00000ea4][WARN: 00000002]  Error querying VHDReAttachFilePath (The system can not find the stated file.)
[07:11:34.447][tid:00000ea0.00000ea4][INFO]            VHDPath: C:\windows\TEMP\S-1-5-21-3307134969-3200570010-XXX-2393_RO.VHDX
[07:11:34.447][tid:00000ea0.00000ea4][ERROR:00000002]  WTSQueryUserToken (The system can not find the stated file.)
[07:11:34.447][tid:00000ea0.00000ea4][INFO]            We are supposed to re-attach as the user, but we're unable to.  Trying as computer object.
[07:11:34.447][tid:00000ea0.00000ea4][INFO]            Attempting re-attach as the computer
[07:11:34.447][tid:00000ea0.00000ea4][INFO]            Retry Count: 60  Retry Interval (seconds): 10
[07:11:34.462][tid:00000ea0.00000ea4][INFO]            Unsuccessful re-attach attempt.  Retry in 10 seconds.
[07:11:44.478][tid:00000ea0.00000ea4][INFO]            Retrying re-attach (1 of 60)
[07:11:44.478][tid:00000ea0.00000ea4][INFO]            Unsuccessful re-attach attempt.  Retry in 10 seconds.
[07:11:54.494][tid:00000ea0.00000ea4][INFO]            Retrying re-attach (2 of 60)
[07:11:54.494][tid:00000ea0.00000ea4][INFO]            Unsuccessful re-attach attempt.  Retry in 10 seconds.
[07:12:04.510][tid:00000ea0.00000ea4][INFO]            Retrying re-attach (3 of 60)
[07:12:04.510][tid:00000ea0.00000ea4][INFO]            Unsuccessful re-attach attempt.  Retry in 10 seconds.
[07:12:14.526][tid:00000ea0.00000ea4][INFO]            Retrying re-attach (4 of 60)
[07:12:14.526][tid:00000ea0.00000ea4][INFO]            Unsuccessful re-attach attempt.  Retry in 10 seconds.
[07:12:24.541][tid:00000ea0.00000ea4][INFO]            Retrying re-attach (5 of 60)
[07:12:24.541][tid:00000ea0.00000ea4][INFO]            Unsuccessful re-attach attempt.  Retry in 10 seconds.
[07:12:34.557][tid:00000ea0.00000ea4][INFO]            Retrying re-attach (6 of 60)
[07:12:34.557][tid:00000ea0.00000ea4][INFO]            Unsuccessful re-attach attempt.  Retry in 10 seconds.

FSL2.txt

[07:53:04.861][tid:00000ea0.00002c40][INFO]              Removal of folder redirection complete
[07:53:04.917][tid:00000ea0.00002c40][INFO]              Export profile registry info complete
[07:53:04.917][tid:00000ea0.00002c40][INFO]              Configuration setting not found: SOFTWARE\FSLogix\Profiles\GroupPolicyState.  Using default: 0
[07:53:04.918][tid:00000ea0.00002c40][INFO]              Removed redirection from C:\Users\xentest
[07:53:04.918][tid:00000ea0.00002c40][ERROR:00000091]    RemoveDirectory failure C:\Users\xentest (Das Verzeichnis ist nicht leer.)
[07:53:04.918][tid:00000ea0.00002c40][INFO]              Configuration setting not found: SOFTWARE\FSLogix\Profiles\ControlTileService.  Using default: 0
[07:53:04.918][tid:00000ea0.00002c40][INFO]              Opening RW diff disk: \\hartfs01.domain.local\profiles_ctx$\xentest_S-1-5-21-3307134969-3200570010-XXX-4611\RW.VHDX
[07:53:05.051][tid:00000ea0.00002c40][INFO]              Detached vhd(x)
[07:53:05.051][tid:00000ea0.00002c40][INFO]              VHD(x) Detach request returning after 141 milliseconds
[07:53:05.052][tid:00000ea0.00002c40][INFO]              Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\KeepLocalDir.  Data: 0
[07:53:05.052][tid:00000ea0.00002c40][INFO]              Directory removal queued: C:\Users\local_xentest1
[07:53:05.052][tid:00000ea0.00002c40][INFO]              Device cleanup queued
[07:53:05.052][tid:00000ea0.00002c40][INFO]              Configuration setting not found: SOFTWARE\FSLogix\Profiles\DeleteProfileOnLogoff.  Using default: 1
[07:53:05.052][tid:00000ea0.00002c40][INFO]              Configuration setting not found: SOFTWARE\FSLogix\Profiles\DeleteProfileTimeout.  Using default: 30000
[07:53:05.052][tid:00000ea0.00002040][INFO]           ===== Begin Session:    Remove Local Directory
[07:53:05.053][tid:00000ea0.000022e0][INFO]               Deleting profile on logoff
[07:53:05.153][tid:00000ea0.00000bf8][INFO]           ===== Begin Session:     Remove Unused Device Information
[07:53:05.176][tid:00000ea0.00002040][INFO]                Successfully removed C:\Users\local_xentest1
[07:53:05.183][tid:00000ea0.00000bf8][INFO]                Devices removed: 2. Errors: 0
[07:53:05.183][tid:00000ea0.00000bf8][INFO]           ===== End Session:     Remove Unused Device Information
[07:53:05.245][tid:00000ea0.00002040][INFO]               Successfully removed C:\Users\local_xentest
[07:53:05.245][tid:00000ea0.00002040][INFO]           ===== End Session:    Remove Local Directory
[07:53:05.515][tid:00000ea0.000022e0][ERROR:00000490]    Failed to Remove Profile for sid S-1-5-21-3307134969-3200570010-XXX-4611 (Element not found.)
[07:53:05.515][tid:00000ea0.000022e0][ERROR:00000002]    Error removing profile key for sid S-1-5-21-3307134969-3200570010-XXX-4611 (The system can not find the stated file.)
[07:53:05.516][tid:00000ea0.00002c40][INFO]              Root VHD: \\hartfs01.domain.local\profiles_ctx$\xentest_S-1-5-21-3307134969-3200570010-XXX-4611\Profile_xentest.VHDX
[07:53:05.516][tid:00000ea0.00002c40][INFO]              RW Diff disk: \\hartfs01.domain.local\profiles_ctx$\xentest_S-1-5-21-3307134969-3200570010-XXX-4611\RW.VHDX
[07:53:05.516][tid:00000ea0.00002c40][INFO]              RO Diff disk: C:\windows\TEMP\S-1-5-21-3307134969-3200570010-XXX-4611_RO.VHDX
[07:53:05.517][tid:00000ea0.00002c40][INFO]              Attempting merge of diff disk: \\hartfs01.domain.local\profiles_ctx$\xentest_S-1-5-21-3307134969-3200570010-XXX-4611\RW.VHDX
[07:53:05.535][tid:00000ea0.00002c40][INFO]              Opened diff disk.  Attempting merge.
[07:53:05.613][tid:00000ea0.00002c40][INFO]              Merge successful
[07:53:05.613][tid:00000ea0.00002c40][INFO]              Merged RW diff: \\hartfs01.domain.local\profiles_ctx$\xentest_S-1-5-21-3307134969-3200570010-XXX-4611\RW.VHDX
[07:53:05.615][tid:00000ea0.00002c40][INFO]              UnloadProfile successful.  User: xentest. SID: S-1-5-21-3307134969-3200570010-XXX-4611.
[07:53:05.615][tid:00000ea0.00002c40][INFO]              unloadProfile time: 1015 milliseconds

FSL3.txt

[07:57:45.390][tid:00000ea0.00000ea4][INFO]            Unsuccessful re-attach attempt.  Retry in 10 seconds.
[07:57:55.390][tid:00000ea0.00000ea4][INFO]            Retrying re-attach (57 of 60)
[07:57:55.398][tid:00000ea0.00000ea4][INFO]            Unsuccessful re-attach attempt.  Retry in 10 seconds.
[07:58:05.398][tid:00000ea0.00000ea4][INFO]            Retrying re-attach (58 of 60)
[07:58:05.406][tid:00000ea0.00000ea4][INFO]            Unsuccessful re-attach attempt.  Retry in 10 seconds.
[07:58:15.407][tid:00000ea0.00000ea4][INFO]            Retrying re-attach (59 of 60)
[07:58:15.415][tid:00000ea0.00000ea4][INFO]            Max retries reached.  Giving up re-attach attempts.
[07:58:15.415][tid:00000ea0.00000ea4][ERROR:c03a000e]  OpenVirtualDisk (The virtual disk chain is damaged. The identifier of the parent virtual disk and the identifier of the differing disk conflict.)
[07:58:15.415][tid:00000ea0.00000ea4][INFO]           ===== End Session: Volume re-attach
[07:58:15.417][tid:00000ea0.00000ea4][INFO]           Configuration setting not found: SOFTWARE\FSLogix\Profiles\ReAttachRetryCount.  Using default: 60
[07:58:15.417][tid:00000ea0.00000ea4][INFO]           Configuration setting not found: SOFTWARE\FSLogix\Profiles\ReAttachIntervalSeconds.  Using default: 10
[07:58:15.417][tid:00000ea0.00000ea4][INFO]           ===== Begin Session: Volume re-attach
[07:58:15.417][tid:00000ea0.00000ea4][INFO]            Attempting re-attach of volume: \\?\Volume{f9af2c8e-7617-4e92-a2a9-71d301a2e7b6}\ for SID: S-1-5-21-3307134969-3200570010-XXX-2393
[07:58:15.417][tid:00000ea0.00000ea4][INFO]            Configuration setting not found: SOFTWARE\FSLogix\Profiles\LogonSyncMutexTimeout.  Using default: 60000
[07:58:15.417][tid:00000ea0.00000ea4][INFO]            Acquired reattach virtual disk lock for user S-1-5-21-3307134969-3200570010-XXX-2393 (Elapsed time: 0)
[07:58:15.417][tid:00000ea0.00000ea4][WARN: 00000002]  Error querying VHDReAttachFilePath (The system can not find the stated file.)
[07:58:15.417][tid:00000ea0.00000ea4][INFO]            VHDPath: C:\windows\TEMP\S-1-5-21-3307134969-3200570010-XXX-2393_RO.VHDX
[07:58:15.417][tid:00000ea0.00000ea4][ERROR:00000002]  WTSQueryUserToken (The system can not find the stated file.)
[07:58:15.417][tid:00000ea0.00000ea4][INFO]            We are supposed to re-attach as the user, but we're unable to.  Trying as computer object.
[07:58:15.417][tid:00000ea0.00000ea4][INFO]            Attempting re-attach as the computer
[07:58:15.417][tid:00000ea0.00000ea4][INFO]            Retry Count: 60  Retry Interval (seconds): 10
[07:58:15.428][tid:00000ea0.00000ea4][INFO]            Unsuccessful re-attach attempt.  Retry in 10 seconds.
[07:58:25.429][tid:00000ea0.00000ea4][INFO]            Retrying re-attach (1 of 60)
[07:58:25.437][tid:00000ea0.00000ea4][INFO]            Unsuccessful re-attach attempt.  Retry in 10 seconds.

Eventlog

Event1.txt

Driver installation failed. Result = 0x80070422 für devnode "STORAGE\VOLUME\{17941A03-3A00-11EB-91B8-806E6F6E6963}#0000000000010000".
Driver installation failed. Result = 0x80070422 für devnode "SCSI\DISK&VEN_VMWARE&PROD_VIRTUAL_DISK\5&22BE343F&0&000100".
Driver installation failed. Result = 0x80070422 für devnode "SCSI\DISK&VEN_VMWARE&PROD_VIRTUAL_DISK\5&22BE343F&0&000200".
Driver installation failed. Result = 0x80070422 für devnode "STORAGE\VOLUME\{17941A04-3A00-11EB-91B8-806E6F6E6963}#0000000000100000".
Driver installation failed. Result = 0x80070422 für devnode "TERMINPUT_BUS\UMB\2&2C22BCC9&0&SESSION2KEYBOARD0".
Driver installation failed. Result = 0x80070422 für devnode "TERMINPUT_BUS\UMB\2&2C22BCC9&0&SESSION2MOUSE0".
Driver installation failed. Result = 0x80070422 für devnode "STORAGE\VOLUME\{17941A03-3A00-11EB-91B8-806E6F6E6963}#0000000000010000".
Driver installation failed. Result = 0x80070422 für devnode "SCSI\DISK&VEN_VMWARE&PROD_VIRTUAL_DISK\5&22BE343F&0&000100".
Driver installation failed. Result = 0x80070422 für devnode "SCSI\DISK&VEN_VMWARE&PROD_VIRTUAL_DISK\5&22BE343F&0&000200".
Driver installation failed. Result = 0x80070422 für devnode "STORAGE\VOLUME\{17941A04-3A00-11EB-91B8-806E6F6E6963}#0000000000100000".
Driver installation failed. Result = 0x80070422 für devnode "TERMINPUT_BUS\UMB\2&2C22BCC9&0&SESSION2KEYBOARD0".
Driver installation failed. Result = 0x80070422 für devnode "TERMINPUT_BUS\UMB\2&2C22BCC9&0&SESSION2MOUSE0".
Driver installation failed. Result = 0x80070422 für devnode "SCSI\DISK&VEN_MSFT&PROD_VIRTUAL_DISK\2&1F4ADFFE&0&000003".
Driver installation failed. Result = 0x80070422 für devnode "SCSI\DISK&VEN_MSFT&PROD_VIRTUAL_DISK\2&1F4ADFFE&0&000004".
Driver installation failed. Result = 0x80070422 für devnode "SWD\MMDEVAPI\{3.0.0.00000004}.{61654801-7364-7465-2045-617270686F00}".
Driver installation failed. Result = 0x80070422 für devnode "SWD\MMDEVAPI\{3.0.1.00000003}.{6B694D02-6F72-6F66-6E20-284E56494400}".
Driver installation failed. Result = 0x80070422 für devnode "SWD\MMDEVAPI\{3.0.1.00000003}.{61654802-7364-7465-204D-6963726F7000}".
Driver installation failed. Result = 0x80070422 für devnode "SWD\MMDEVAPI\{3.0.0.00000003}.{75614C01-7374-7270-6563-686572202800}".
Driver installation failed. Result = 0x80070422 für devnode "SWD\MMDEVAPI\{3.0.0.00000003}.{65705301-6B61-7265-7320-284E56494400}".
Driver installation failed. Result = 0x80070422 für devnode "SWD\MMDEVAPI\{3.0.0.00000003}.{61654801-7364-7465-2045-617270686F00}".

Author: Marco

Marco is an IT-System administrator and IT-Consultant with 10+ years experience. He is specialized in the delivery of virtual Apps and Desktops with Citrix solutions. In 2017 he has been awarded Citrix Technology Advocate by Citrix for his community work (#CTA). His second core area is availability & performance monitoring with Zabbix, a leading open-source solution. His employer is the German IT-Company ANAXCO, which is developing a Transport Management Software (TMS) based on Microsoft Dynamics AX. More about Marco View all posts by Marco

Was facing this recently, solution was using GPOs to configure RDS inactive and idle disconnect times, we also applied the reg key for cleanupinvalidsessions with value to each SessionHost. Also had this script handy but didn’t implement it, did test it from cloudshell.
GPO added to session hosts OU for sessions, I didn’t configure anything for active sessions and setup two hour time outs for idle and disconnected sessions to allow an hour or so for lunch.

In the Group Policy Management Editor, navigate to Computer Configuration > Policies > Administrative Templates > Windows Components > Remote Desktop Services > Remote Desktop Session Host > Session Time Limits.

Script to fix session hosts, run from azure portal using run as, if i was feeling fancy I would use a get-azvm in there and a parralell flag to do it at once, but only had a few session hosts to run it against, make this change on golden image if you can.
$registryPath = “HKCU:\Software\fslogix\apps”

$Name = “CleanupInvalidSesions”

$value = “1”

IF(!(Test-Path $registryPath))

{

New-Item -Path $registryPath -Force | Out-Null

New-ItemProperty -Path $registryPath -Name $name -Value $value -PropertyType DWORD -Force | Out-Null}

ELSE {