none
FsLogix not releasing RW.vhdx Lock and merging changes RRS feed

  • Question

  • I have been evaluating FSLogix and had plenty of success in my development environment.  Once moving the same settings to test however, FSLogix is working for some users but not others.  For those it's not working for symptoms are UPM profiles are still in use, FSLogix creates profile directory and VHDX files but never releases the lock on RW.vhdx so changes never merge.  Also seeing "Error set to 1168" and "No teardown required" in the FSLogix logs for the users where it fails.  I must be missing something but have looked over policy, permissions, config, uninstall/reinstall FSLogix, deny old UPN profile directory and running out of ideas.  After login and launching frxtray for a "broken" user (which is pretty much anyone who hasnt previously logged onto the test environment), the tool reports "Inactive - Unknown Status 4294967295".  FSL logs below:

    [13:26:42.701][tid:00000f24.00002650][INFO]           ===== Begin Session: Logon
    [13:26:42.701][tid:00000f24.00002650][INFO]            User: S-1-5-21-505881439-82067924-1220176271-599243 (UserTest)
    [13:26:42.701][tid:00000f24.00002650][INFO]            Acquiring mutex for user logon
    [13:26:42.701][tid:00000f24.00002650][INFO]            Configuration setting not found: SOFTWARE\FSLogix\Profiles\LogonSyncMutexTimeout.  Using default: 60000
    [13:26:42.701][tid:00000f24.00002650][INFO]            Mutex acquired
    [13:26:42.701][tid:00000f24.00002650][INFO]           ===== Begin Session:  LoadProfile: UserTest
    [13:26:42.701][tid:00000f24.00002650][INFO]             Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\Enabled.  Data: 1
    [13:26:42.701][tid:00000f24.00002650][INFO]             User: UserTest. SID: S-1-5-21-505881439-82067924-1220176271-599243.
    [13:26:42.701][tid:00000f24.00002650][INFO]             Include group SID: S-1-5-21-265106384-2251368462-1354977876-1003
    [13:26:42.701][tid:00000f24.00002650][INFO]             Exclude group SID: S-1-5-21-265106384-2251368462-1354977876-1004
    [13:26:42.701][tid:00000f24.00002650][INFO]             User is a member of the include group
    [13:26:42.701][tid:00000f24.00002650][INFO]             Status set to 200: Setup in progress
    [13:26:42.701][tid:00000f24.00002650][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\RedirectType.  Using default: 2
    [13:26:42.701][tid:00000f24.00002650][INFO]             Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\ConcurrentUserSessions.  Data: 1
    [13:26:42.701][tid:00000f24.00002650][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\VolumeWaitTimeMS.  Using default: 20000
    [13:26:42.701][tid:00000f24.00002650][INFO]             Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\DeleteLocalProfileWhenVHDShouldApply.  Data: 1
    [13:26:42.701][tid:00000f24.00002650][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\FSLogixShellPath.  Using default: 
    [13:26:42.701][tid:00000f24.00002650][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\AccessNetworkAsComputerObject.  Using default: 0
    [13:26:42.701][tid:00000f24.00002650][INFO]             Accessing network as user object
    [13:26:42.701][tid:00000f24.00002650][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\AttachVHDSDDL.  Using default: 
    [13:26:42.701][tid:00000f24.00002650][ERROR:00000020]   Delete profile failed for sid S-1-5-21-505881439-82067924-1220176271-599243, Cleaning up manually. (The process cannot access the file because it is being used by another process.)
    [13:26:42.701][tid:00000f24.00002650][INFO]             Removing local profile for user: S-1-5-21-505881439-82067924-1220176271-599243
    [13:26:45.248][tid:00000f24.00002650][ERROR:00000020]   Error removing: C:\Users\UserTest (The process cannot access the file because it is being used by another process.)
    [13:26:45.248][tid:00000f24.00002650][INFO]             Successfully removed: HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\ProfileList\S-1-5-21-505881439-82067924-1220176271-599243
    [13:26:45.248][tid:00000f24.00002650][INFO]             Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\ProfileType.  Data: 3
    [13:26:45.248][tid:00000f24.00002650][INFO]             Profile type: If first then Read/Write
    [13:26:45.248][tid:00000f24.00002650][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\CCDLocations.  Using default: 
    [13:26:45.248][tid:00000f24.00002650][INFO]             Configuration Read (REG_SZ): SOFTWARE\FSLogix\Profiles\VHDLocations.
    [13:26:45.248][tid:00000f24.00002650][INFO]             VHDLocations found - configured to use Local Disk
    [13:26:45.248][tid:00000f24.00002650][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\DiffDiskParentFolderPath.  Using default: C:\Windows\TEMP\
    [13:26:45.248][tid:00000f24.00002650][INFO]             Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\NoProfileContainingFolder.  Data: 1
    [13:26:45.248][tid:00000f24.00002650][INFO]             Configuration Read (REG_SZ): SOFTWARE\FSLogix\Profiles\VHDNameMatch.  Data: %username%_%sid%
    [13:26:45.248][tid:00000f24.00002650][INFO]             Configuration Read (REG_SZ): SOFTWARE\FSLogix\Profiles\VolumeType.  Data: VHDX
    [13:26:45.248][tid:00000f24.00002650][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\DisableRegistryLocalRedirect.  Using default: 1
    [13:26:45.248][tid:00000f24.00002650][INFO]             Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\LockedRetryCount.  Data: 3
    [13:26:45.248][tid:00000f24.00002650][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\LockedRetryInterval.  Using default: 5
    [13:26:45.248][tid:00000f24.00002650][INFO]             Profile VHD Path: \\ctx-profiles.yu.yale.edu\profilecontainers\UserTest\UserTest_S-1-5-21-505881439-82067924-1220176271-599243.VHDX
    [13:26:45.248][tid:00000f24.00002650][INFO]             Configuration Read (REG_SZ): SOFTWARE\FSLogix\Profiles\VHDNamePattern.  Data: %username%_%sid%
    [13:26:45.248][tid:00000f24.00002650][INFO]             Attempting merge of diff disk: \\ctx-profiles.yu.yale.edu\profilecontainers\UserTest\RW.VHDX
    [13:26:45.279][tid:00000f24.00002650][INFO]             One of the VHDs to merge is open in another session
    [13:26:45.279][tid:00000f24.00002650][INFO]             RW diff disk is open in another session
    [13:26:45.279][tid:00000f24.00002650][INFO]             RW exists.  Taking RO role.
    [13:26:45.279][tid:00000f24.00002650][ERROR:00000020]   Deleting file: C:\Windows\TEMP\S-1-5-21-505881439-82067924-1220176271-599243_RO.VHDX (The process cannot access the file because it is being used by another process.)
    [13:26:45.279][tid:00000f24.00002650][ERROR:00000050]   Creating RO diff: C:\Windows\TEMP\S-1-5-21-505881439-82067924-1220176271-599243_RO.VHDX (The file exists.)
    [13:26:45.279][tid:00000f24.00002650][INFO]             Status set to 22: Error handling profile
    [13:26:45.279][tid:00000f24.00002650][INFO]             Error set to 80
    [13:26:45.279][tid:00000f24.00002650][ERROR:00000050]   handleProfileType error (The file exists.)
    [13:26:45.279][tid:00000f24.00002650][INFO]             Error. Cleaning up.
    [13:26:45.279][tid:00000f24.00002650][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\PreventLoginWithFailure.  Using default: 0
    [13:26:45.279][tid:00000f24.00002650][ERROR:00000057]   LoadProfile failed.  User: UserTest. SID: S-1-5-21-505881439-82067924-1220176271-599243. (The parameter is incorrect.)
    [13:26:45.279][tid:00000f24.00002650][INFO]             loadProfile time: 2578 milliseconds
    [13:26:45.279][tid:00000f24.00002650][INFO]           ===== End Session:  LoadProfile: UserTest
    [13:26:45.279][tid:00000f24.00002650][INFO]           ===== End Session: Logon
    [13:26:52.451][tid:00000f24.00002650][INFO]           ===== Begin Session: StartShell
    [13:26:52.451][tid:00000f24.00002650][INFO]            User: S-1-5-21-505881439-82067924-1220176271-599243 (UserTest)
    [13:26:52.451][tid:00000f24.00002650][INFO]            Acquiring mutex for user logon
    [13:26:52.451][tid:00000f24.00002650][INFO]            Configuration setting not found: SOFTWARE\FSLogix\Profiles\LogonSyncMutexTimeout.  Using default: 60000
    [13:26:52.451][tid:00000f24.00002650][INFO]            Mutex acquired
    [13:26:52.498][tid:00000f24.00002650][INFO]           ===== Begin Session:  Logon notification: UserTest
    [13:26:52.498][tid:00000f24.00002650][INFO]             Session configuration read (REG_SZ): SOFTWARE\FSLogix\Profiles\Sessions\S-1-5-21-505881439-82067924-1220176271-599243\ActivityId = 'a1f4a82e-cb1d-0006-bc02-f5a11dcbd501'
    [13:26:52.498][tid:00000f24.00002650][INFO]             Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\ConcurrentUserSessions.  Data: 1
    [13:26:52.498][tid:00000f24.00002650][INFO]             Checking Profile Data Export for S-1-5-21-505881439-82067924-1220176271-599243
    [13:26:52.498][tid:00000f24.00002650][INFO]             Error set to 80
    [13:26:52.498][tid:00000f24.00002650][INFO]             Not a profile we care about
    [13:26:52.498][tid:00000f24.00002650][INFO]           ===== End Session:  Logon notification: UserTest
    [13:26:52.732][tid:00000f24.00000f50][INFO]            Volume attach event
    [13:26:52.841][tid:00000f24.00002650][INFO]           ===== End Session: StartShell
    [13:28:40.373][tid:00000f24.00002650][INFO]           ===== Begin Session: EndShell
    [13:28:40.373][tid:00000f24.00002650][INFO]            User: S-1-5-21-505881439-82067924-1220176271-599243 (UserTest)
    [13:28:40.373][tid:00000f24.00002650][INFO]            Acquiring mutex for user logoff
    [13:28:40.373][tid:00000f24.00002650][INFO]            Configuration setting not found: SOFTWARE\FSLogix\Profiles\LogonSyncMutexTimeout.  Using default: 60000
    [13:28:40.373][tid:00000f24.00002650][INFO]            Mutex acquired
    [13:28:40.607][tid:00000f24.00000f50][INFO]            Configuration setting not found: SOFTWARE\FSLogix\Profiles\ReAttachRetryCount.  Using default: 60
    [13:28:40.607][tid:00000f24.00000f50][INFO]            Configuration setting not found: SOFTWARE\FSLogix\Profiles\ReAttachIntervalSeconds.  Using default: 10
    [13:28:40.607][tid:00000f24.00000f50][INFO]           ===== Begin Session:  Volume re-attach
    [13:28:40.607][tid:00000f24.00000f50][INFO]           ===== End Session:  Volume re-attach
    [13:28:40.717][tid:00000f24.00002650][INFO]            Session configuration read (REG_SZ): SOFTWARE\FSLogix\Profiles\Sessions\S-1-5-21-505881439-82067924-1220176271-599243\ActivityId = 'a1f4a82e-cb1d-0006-bc02-f5a11dcbd501'
    [13:28:40.717][tid:00000f24.00002650][INFO]            Error set to 80
    [13:28:40.717][tid:00000f24.00002650][INFO]           ===== End Session: EndShell
    [13:28:45.873][tid:00000f24.00002650][INFO]           ===== Begin Session: Logoff
    [13:28:45.873][tid:00000f24.00002650][INFO]            User: S-1-5-21-505881439-82067924-1220176271-599243 (UserTest)
    [13:28:45.873][tid:00000f24.00002650][INFO]            Acquiring Lock for user logoff
    [13:28:45.873][tid:00000f24.00002650][INFO]            Configuration setting not found: SOFTWARE\FSLogix\Profiles\LogonSyncMutexTimeout.  Using default: 60000
    [13:28:45.873][tid:00000f24.00002650][INFO]            Mutex acquired
    [13:28:45.873][tid:00000f24.00002650][INFO]           ===== Begin Session:  Unload profile: UserTest
    [13:28:45.873][tid:00000f24.00002650][INFO]             User: UserTest. SID: S-1-5-21-505881439-82067924-1220176271-599243.
    [13:28:45.873][tid:00000f24.00002650][INFO]             Session configuration read (REG_SZ): SOFTWARE\FSLogix\Profiles\Sessions\S-1-5-21-505881439-82067924-1220176271-599243\ActivityId = 'a1f4a82e-cb1d-0006-bc02-f5a11dcbd501'
    [13:28:45.873][tid:00000f24.00002650][INFO]             Error set to 80
    [13:28:45.873][tid:00000f24.00002650][INFO]             Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\ConcurrentUserSessions.  Data: 1
    [13:28:45.873][tid:00000f24.00002650][INFO]             Profile refcount decremented to: -1
    [13:28:45.873][tid:00000f24.00002650][INFO]             No teardown required
    [13:28:45.873][tid:00000f24.00002650][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\ShutdownOnUserLogoff.  Using default: 0
    [13:28:45.873][tid:00000f24.00002650][INFO]             Configuration setting not found: SOFTWARE\FSLogix\Profiles\RebootOnUserLogoff.  Using default: 0
    [13:28:45.873][tid:00000f24.00002650][INFO]             UnloadProfile successful.  User: UserTest. SID: S-1-5-21-505881439-82067924-1220176271-599243.
    [13:28:45.873][tid:00000f24.00002650][INFO]             unloadProfile time: 0 milliseconds
    [13:28:45.873][tid:00000f24.00002650][INFO]           ===== End Session:  Unload profile: UserTest
    [13:28:45.873][tid:00000f24.00002650][INFO]           ===== End Session: Logoff

    Wednesday, January 15, 2020 6:59 PM

All replies

  • I may have solved it, will post updates tomorrow after more testing to confirm it's been addressed.
    Wednesday, January 15, 2020 9:04 PM
  • We discovered a citrix policy causing this issue.  Strangely it affected only new users and not existing users with FSL profiles already in the environment.
    • Edited by Adam H Thursday, January 16, 2020 6:11 PM
    Thursday, January 16, 2020 6:10 PM
  • Could you point what what Citrix policy was causing you issues?

    Thank you!

    Friday, January 17, 2020 7:05 PM
  • Please, can you explain waht policy it was?

    I guess I see something similar.

    Thank you.

    Tuesday, February 11, 2020 10:22 AM
  • what was the Citrix Policy that was causing the issue?

    Thanks


    Stephen

    Tuesday, February 11, 2020 9:48 PM