Random issue: Can't connect to existing FSLogix Profile container

Nick Panaccio 11 Reputation points
2021-05-07T11:57:09.21+00:00

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.

Windows for business Windows Client for IT Pros User experience FSLogix
{count} votes

1 answer

Sort by: Most helpful
  1. Nick Panaccio 11 Reputation points
    2021-05-10T14:22:26.96+00:00

    We actually resolved this issue over the weekend. It looks like when our storage team added more front end nodes to our EMC Isilon, FSLogix started to fail 20% of the time. We went from 6 nodes to 10. Once we dropped Isilon back down to 6 nodes for this storage location, loading FSLogix profiles went back to a 100% success rate. I have no idea why that is, honestly. I opened a ticket with Microsoft, and the network engineer who looked at the Wireshark logs said that she couldn't even see it getting to the share itself.


Your answer

Answers can be marked as Accepted Answers by the question author, which helps users to know the answer solved the author's problem.