I'm having issues with FSLogix over the last two days that has me stumped. The issue appears to be random, because it doesn't happen all the time. When I logon to my Citrix desktop (W10, 1912 CU2, FSL 2.9.7349), it doesn't always load my profile. Half of the time, it eventually times out and logs me on with a temporary local profile. The other half of the time, it loads just fine. In the Profile log, I see this:
[07:43:22.779][tid:00001450.00000760][INFO] ===== Begin Session: Logon
[07:43:22.779][tid:00001450.00000760][INFO] User: S-1-5-21-1275210071-220523388-725345543-251799 (testuser)
[07:43:22.779][tid:00001450.00000760][INFO] Acquiring mutex for user logon
[07:43:22.779][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\LogonSyncMutexTimeout. Using default: 60000
[07:43:22.779][tid:00001450.00000760][INFO] Mutex acquired
[07:43:22.779][tid:00001450.00000760][INFO] ===== Begin Session: LoadProfile: testuser
[07:43:22.779][tid:00001450.00000760][INFO] Configuration Read (DWORD): SOFTWARE\FSLogix\Profiles\Enabled. Data: 1
[07:43:22.779][tid:00001450.00000760][INFO] User: testuser. SID: S-1-5-21-1275210071-220523388-725345543-251799.
[07:43:22.779][tid:00001450.00000760][INFO] Include group SID: S-1-5-21-2750255506-3374091724-527744386-1150
[07:43:22.779][tid:00001450.00000760][INFO] Exclude group SID: S-1-5-21-2750255506-3374091724-527744386-1151
[07:43:22.779][tid:00001450.00000760][INFO] User is a member of the include group
[07:43:22.779][tid:00001450.00000760][INFO] Status set to 200: Setup in progress
[07:43:22.779][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\RedirectType. Using default: 2
[07:43:22.779][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\ConcurrentUserSessions. Using default: 1
[07:43:22.779][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\VolumeWaitTimeMS. Using default: 20000
[07:43:22.779][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\DeleteLocalProfileWhenVHDShouldApply. Using default: 0
[07:43:22.779][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\FSLogixShellPath. Using default:
[07:43:22.779][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\AccessNetworkAsComputerObject. Using default: 0
[07:43:22.779][tid:00001450.00000760][INFO] Accessing network as user object
[07:43:22.779][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\AttachVHDSDDL. Using default:
[07:43:22.779][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\ProfileType. Using default: 0
[07:43:22.779][tid:00001450.00000760][INFO] Profile type: Normal
[07:43:22.779][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\CCDLocations. Using default:
[07:43:22.779][tid:00001450.00000760][INFO] Configuration Read (REG_SZ): SOFTWARE\FSLogix\Profiles\VHDLocations.
[07:43:22.779][tid:00001450.00000760][INFO] VHDLocations found - configured to use Local Disk
[07:43:22.779][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\DiffDiskParentFolderPath. Using default: C:\WINDOWS\TEMP\
[07:43:22.779][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\NoProfileContainingFolder. Using default: 0
[07:43:22.779][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\FlipFlopProfileDirectoryName. Using default: 0
[07:43:22.779][tid:00001450.00000760][INFO] Configuration Read (REG_SZ): SOFTWARE\FSLogix\Profiles\SIDDirNameMatch. Data: %username%
[07:43:22.779][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\VHDNameMatch. Using default: Profile*
[07:43:22.779][tid:00001450.00000760][INFO] Configuration Read (REG_SZ): SOFTWARE\FSLogix\Profiles\VolumeType. Data: VHDX
[07:43:55.391][tid:00001450.00000760][ERROR:00000043] FindFile failed for path: \\domain.com\Citrix\FSLogix\testuser\Profile*.VHDX (The network name cannot be found.)
[07:43:55.391][tid:00001450.00000760][INFO] Configuration Read (REG_SZ): SOFTWARE\FSLogix\Profiles\SIDDirNamePattern. Data: %username%
[07:43:55.391][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\VHDNamePattern. Using default: Profile_%username%
[07:45:00.429][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\DisableRegistryLocalRedirect. Using default: 1
[07:45:00.429][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\LockedRetryCount. Using default: 12
[07:45:00.429][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\LockedRetryInterval. Using default: 5
[07:45:00.429][tid:00001450.00000760][INFO] Profile VHD not found. Creating new VHD.
[07:45:00.429][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\DirectAttachOnCreateVHD. Using default: FALSE
[07:45:00.429][tid:00001450.00000760][INFO] Status set to 1: Cannot load user's profile
[07:45:00.429][tid:00001450.00000760][INFO] Error set to 1064
[07:45:00.429][tid:00001450.00000760][ERROR:00000428] Unable to find parent path of "" (An exception occurred in the service when handling the control request.)
[07:45:00.429][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\PreventLoginWithFailure. Using default: 0
[07:45:00.429][tid:00001450.00000760][ERROR:00000428] LoadProfile failed. User: testuser. SID: S-1-5-21-1275210071-220523388-725345543-251799. (An exception occurred in the service when handling the control request.)
[07:45:00.429][tid:00001450.00000760][INFO] loadProfile time: 97641 milliseconds
[07:45:00.429][tid:00001450.00000760][INFO] ===== End Session: LoadProfile: testuser
[07:45:00.429][tid:00001450.00000760][INFO] ===== End Session: Logon
[07:45:01.007][tid:00001450.00001ab0][INFO] ===== Begin Session: Profile Directory Changed: S-1-5-21-1275210071-220523388-725345543-251799
[07:45:01.007][tid:00001450.00001ab0][INFO] New Profile Directory: C:\Users\testuser
[07:45:01.007][tid:00001450.00001ab0][INFO] Error set to 1064
[07:45:01.007][tid:00001450.00001ab0][INFO] ===== End Session: Profile Directory Changed: S-1-5-21-1275210071-220523388-725345543-251799
[07:45:04.851][tid:00001450.00000760][INFO] ===== Begin Session: StartShell
[07:45:04.851][tid:00001450.00000760][INFO] User: S-1-5-21-1275210071-220523388-725345543-251799 (testuser)
[07:45:04.851][tid:00001450.00000760][INFO] Acquiring mutex for user logon
[07:45:04.851][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\LogonSyncMutexTimeout. Using default: 60000
[07:45:04.851][tid:00001450.00000760][INFO] Mutex acquired
[07:45:05.023][tid:00001450.00000760][INFO] ===== Begin Session: Logon notification: testuser
[07:45:05.023][tid:00001450.00000760][INFO] Session configuration read (REG_SZ): SOFTWARE\FSLogix\Profiles\Sessions\S-1-5-21-1275210071-220523388-725345543-251799\ActivityId = 'e91207fa-4330-0000-cb18-12e93043d701'
[07:45:05.023][tid:00001450.00000760][INFO] Configuration setting not found: SOFTWARE\FSLogix\Profiles\ConcurrentUserSessions. Using default: 1
[07:45:05.023][tid:00001450.00000760][INFO] Checking Profile Data Export for S-1-5-21-1275210071-220523388-725345543-251799
[07:45:05.023][tid:00001450.00000760][INFO] Error set to 1064
[07:45:05.023][tid:00001450.00000760][INFO] No user VHD has been attached. This is not a profile we should handle
[07:45:05.023][tid:00001450.00000760][INFO] ===== End Session: Logon notification: testuser
[07:45:05.039][tid:00001450.00000760][INFO] ===== End Session: StartShell
In Event Viewer, there are two related entries:
The winlogon notification subscriber <frxsvc> took 97 second(s) to handle the notification event (Logon).
The winlogon notification subscriber <frxsvc> is taking long time to handle the notification event (Logon).
My storage guys are looking into it, but so far saying everything looks fine. The containers are stored on a share on our EMC Isilon, accessed via a DFS path. Any ideas here? The randomness of it all is really throwing me off.