Annoying wait time and ERROR when starting Edge

[vmstrom]

Hi!

Have a problem with 9.2 Edge ini. When entering a vm that i already has been logged in to i get wait time and errors in log like this:

2017-07-16 19:30:43.547 [INFO ] Performing DirectFlex import for config file '\\masterdatalager.master.local\UEMconfig\general\Windows Settings\Edge.INI' [IFP#fe5b876f-9ed99>>]

2017-07-16 19:30:43.547 [DEBUG]    User: master\pewe, Computer: VM-W10X64STD-05, OS: x64-win10 (Version 1607, BuildNumber 14393.1480, SuiteMask 100, ProductType 1/4, Lang 0409, IE 11.1480.14393.0, App-V 5.2.0.0, VMware VDM 7.1.0.5170901, UEM 9.2.0.701, ProcInfo 1/2/2/2, UTC+02:00D), PTS: 512/5264/1C

2017-07-16 19:30:43.547 [DEBUG]    Using profile archive '\\masterdatalager.master.local\UEMprofiles\pewe\archives\Windows Settings\Edge.zip'

2017-07-16 19:30:43.547 [DEBUG]    Triggered by 'C:\Windows\SystemApps\Microsoft.MicrosoftEdge_8wekyb3d8bbwe\MicrosoftEdge.exe'

2017-07-16 19:30:43.550 [DEBUG] Found flag file for '\\masterdatalager.master.local\UEMconfig\general\Windows Settings\Edge.INI'.

2017-07-16 19:30:43.559 [INFO ] Importing profile archive 'Edge.zip' (\\masterdatalager.master.local\UEMprofiles\pewe\archives\Windows Settings\Edge.zip)

2017-07-16 19:30:43.575 [DEBUG] ImportRegistry::Import: Calling '"C:\Windows\REGEDIT.EXE" /S "C:\Users\pewe\AppData\Local\Temp\FLX7776.tmp"' (RPAL: l=0 (D/P), r=0)

2017-07-16 19:30:56.323 [ERROR] ImportFiles::ImportFile: Access denied on 'LocalAppData/Packages/Microsoft.MicrosoftEdge_8wekyb3d8bbwe/AC/MicrosoftEdge/User/Default/DataStore/Data/nouser1/120712-0049/Favorites/16e930b2d0b35b_Icon.ico'

2017-07-16 19:30:56.325 [ERROR] ImportFiles::ImportFile: Access denied on 'LocalAppData/Packages/Microsoft.MicrosoftEdge_8wekyb3d8bbwe/AC/MicrosoftEdge/User/Default/DataStore/Data/nouser1/120712-0049/Favorites/4b02551de5dc15_Icon.ico'

2017-07-16 19:30:56.328 [ERROR] ImportFiles::ImportFile: Access denied on 'LocalAppData/Packages/Microsoft.MicrosoftEdge_8wekyb3d8bbwe/AC/MicrosoftEdge/User/Default/DataStore/Data/nouser1/120712-0049/Favorites/864b8f8ccf5e50_Icon.ico'

2017-07-16 19:30:56.608 [DEBUG] Read 1451 entries from profile archive (size: 30980735; compressed: 9582813)

2017-07-16 19:30:56.612 [INFO ] Completed DirectFlex import (13071 ms) [<<IFP#fe5b876f-9ed99]

On a vm where my profile is not residing there is no problem.

I let it trig on DirectFlex and have this setting as only from default:

[Metadata]
ProcessIfExists=
DirectFlexEnabled
DirectFlexPath=C:\Windows\SystemApps\Microsoft.MicrosoftEdge_8wekyb3d8bbwe\MicrosoftEdge.exe
DirectFlexPath=C:\Windows\SystemApps\Microsoft.MicrosoftEdge_8wekyb3d8bbwe\MicrosoftEdgeCP.exe
OnlyExportAtLogoff=0
ProcessCriteria=<pc ll='0' t='3' f='0' />

[BinarySettings]
7VS8gJSU17jVuNe55YDkg+a5i7uKvY2/jr+xsfyV9oTrmPeR5cWA5IPm5+fa2uaqxabHq+qa6q7Pu9rkuOiJ6oHgh+KRzYDpiviX5Ivtmbf6k/CC7Z7xl+OmwqXAn6fQtd6nxfaSqsiq3bikpJjUu9i51ZTklNCxxaSaxovigfOc74Dmktez1LGxsbS0PT11Pn0odCdoLnotbD57J2QIaRppDH8jbwBjAm5OHXgMeBF/GGs3ZAttGW4PfRhECWADcR5tAmQQTBtyHHgXYBNPDHkLeRxyBlA1RzRdMlwAQTFBAm0DdxZ/EXQGWgl9EmABZgNfMls4SiVWOV8rBWgBYhB/DGMFcRRwF3ItFWIHbBV3RCAYehhvCi8vZyxvOmY1ejxoP34saTV4EXIAbxxzFWE9cBl6CGcUex1pLEgvSkpKSkpKSu4av8o=

[Immidio Flex]
This file was created using VMware UEM Management Console version 9.2.0.701.
Use only with VMware UEM.

[ijdemes]

Hi vmstrom​,

What kind of user profile type are you using (mandatory, local)?

On a vm where my profile is not residing there is no problem.

Do you mean there are no errors in that case, or that you don't have that big delay (13 seconds), or both?

[vmstrom]

Its local profile. The vms are non-persistent and this happens only when a user enters a vm that he's already been logged into, ie the local profile is already existing. When logging into a vm never been logged in to, normal behaviour.

[ijdemes]

Why don't you let the VM reboot after user logoff? Besides the problem you already experience at the moment with Edge, you may also end up with VM's lacking disk space, because of multiple existing local profiles on them.

[vmstrom]

The problem is not that the vms not getting restarted every time user log off, its the fact that there is local profiles residing on them. As far as i know, there is no safe way to delete local profile at logoff in UEM. We tried it with the ADMX templates and the profile got corrupt. We use to do that in Persona Management in Win 7 and it worked great. When Windows 10 came we decided to go for UEM and its is a real tradeoff to not be able to delete profiles at logoff.

[ijdemes]

I understand. But what I am trying to say is:

You are using a non-persistent VDI environment. If you are not rebooting your VDI VM after logoff and the next or same user logs on to that VM, it is not "that" non-persistent, because there are leftovers from the previous (or same) user.

What I am basically trying to say is, if you are using non-persistent VM's, why not reboot them after the user logs off. By doing that, the (write) delta for that VM is reset and is clean again, without (profile) leftovers from previous users. When a user now logs on, a clean user local user profile is created.

[Raymond_W]

Did you also try to delete the local profile with the UEM advanced template ?

https://kb.vmware.com/kb/2145286

[vmstrom]

Sorry, they are linked clone but persistent. They need to be patched always and we have no resources avalable to patch the golden image and recreate vms all the time.

[vmstrom]

Yes, thats exactly what we tried. But as Pim van der Plis also says in some thread here its not recommended to use it as it corrupts the profile.

[ijdemes]

As far as I know, this advanced setting for deleting the local profile isn't really working well with Windows 10 and therefore not recommended for use with Windows 10 as described in the following thread.

ADMX-based settings

But I am curious to hear if there are different experiences/solutions at this moment.

[ijdemes]

Good timing, I remembered the same thread :smileylaugh:

Any possibility moving over to mandatory profiles with UEM?

[DEMdev]

Hi vmstrom​,

I doubt that this actually is related to profile types, profile persistence, etc...

You're getting access denied errors on a subsequent Edge launch because files are in use. Can you try setting the Export moment to Export at logoff?

[vmstrom]

I guess youre right. When i test this and logoff and logon quick the underlying UEM agent system is doing stuff in background. Thats why i got ERROR, if i wait a couple of minutes there is no ERRORs. What is causing this is ridiculous long time to process 50MB of Edge profile as seen here:

Export at logoff:
2017-07-17 15:28:46.102 [INFO ] Performing DirectFlex export for config file '\\data.master.local\UEMconfig\general\Applications\Edge.INI' [IFP#fd72faab-b5aaa>>]
2017-07-17 15:28:46.102 [DEBUG]    User: MASTER\pewe, Computer: VM-W10X64STD-15, OS: x64-win10 (Version 1607, BuildNumber 14393.1480, SuiteMask 100, ProductType 1/4, Lang 0409, IE 11.1480.14393.0, App-V 5.2.0.0, VMware VDM 7.1.0.5170901, UEM 9.2.0.701, ProcInfo 1/2/2/2, UTC+02:00D), PTS: 5380/5796/1C
2017-07-17 15:28:46.102 [DEBUG]    Using profile archive '\\data.master.local\UEMprofiles\pewe\archives\Applications\Edge.zip'
2017-07-17 15:28:46.102 [DEBUG]    Triggered by 'C:\Windows\SystemApps\Microsoft.MicrosoftEdge_8wekyb3d8bbwe\MicrosoftEdge.exe'
2017-07-17 15:28:46.125 [DEBUG] Using OS-specific extension 'win10'
2017-07-17 15:28:46.126 [INFO ] Exporting profile using config file 'Edge.INI' (\\data.master.local\UEMconfig\general\Applications\Edge.INI)
2017-07-17 15:28:46.147 [INFO ] Exporting Registry information
2017-07-17 15:28:46.147 [DEBUG] ExcludeRegistryTrees: Adding exclusion for 'HKCU\SOFTWARE\Microsoft\MicrosoftEdge\Main'
2017-07-17 15:28:46.147 [DEBUG] ExportRegistry: Exporting tree 'HKCU\SOFTWARE\Classes\Local Settings\Software\Microsoft\Windows\CurrentVersion\AppContainer\Storage\microsoft.microsoftedge_8wekyb3d8bbwe'
2017-07-17 15:28:46.155 [DEBUG] ExportRegistry: Exporting tree 'HKCU\SOFTWARE\Microsoft\MicrosoftEdge'
2017-07-17 15:28:46.155 [INFO ] Exported Registry information successfully
2017-07-17 15:28:46.155 [INFO ] Exporting file information
2017-07-17 15:28:46.155 [DEBUG] ExportFiles: Recursively processing folder '<LocalAppData>\MicrosoftEdge'
2017-07-17 15:28:46.177 [DEBUG] ExportFiles: Recursively processing folder '<LocalAppData>\Packages\Microsoft.MicrosoftEdge_8wekyb3d8bbwe'
2017-07-17 15:29:38.241 [INFO ] Exported file information successfully
2017-07-17 15:29:38.500 [DEBUG] Stored 4145 entries in profile archive (size: 100828771; compressed: 46479378)
2017-07-17 15:29:38.501 [DEBUG] Backup option specified, but no previous profile archive '\\data.master.local\UEMprofiles\pewe\archives\Applications\Edge-win10.zip' found to backup.
2017-07-17 15:29:38.518 [INFO ] Completed DirectFlex export (52421 ms) [<<IFP#fd72faab-b5aaa]

Then i log off and wait a couple of minutes, log in on the same pool again.

Start edge:
2017-07-17 15:44:09.799 [INFO ] Performing DirectFlex import for config file '\\data.master.local\UEMconfig\general\Windows Settings\Edge.INI' [IFP#9485a7d3-1528da>>]
2017-07-17 15:44:09.799 [DEBUG]    User: MASTER\pewe, Computer: VM-W10X64STD-13, OS: x64-win10 (Version 1607, BuildNumber 14393.1480, SuiteMask 100, ProductType 1/4, Lang 0409, IE 11.1480.14393.0, App-V 5.2.0.0, VMware VDM 7.1.0.5170901, UEM 9.2.0.701, ProcInfo 1/2/2/2, UTC+02:00D), PTS: 5860/5636/1C
2017-07-17 15:44:09.799 [DEBUG]    Using profile archive '\\data.master.local\UEMprofiles\pewe\archives\Windows Settings\Edge.zip'
2017-07-17 15:44:09.799 [DEBUG]    Triggered by 'C:\Windows\SystemApps\Microsoft.MicrosoftEdge_8wekyb3d8bbwe\MicrosoftEdge.exe'
2017-07-17 15:44:09.813 [DEBUG] Found flag file for '\\data.master.local\UEMconfig\general\Windows Settings\Edge.INI'.
2017-07-17 15:44:09.824 [INFO ] Importing profile archive 'Edge.zip' (\\data.master.local\UEMprofiles\pewe\archives\Windows Settings\Edge.zip)
2017-07-17 15:44:09.855 [DEBUG] ImportRegistry::Import: Calling '"C:\Windows\REGEDIT.EXE" /S "C:\Users\pewe\AppData\Local\Temp\FLX5709.tmp"' (RPAL: l=0 (D/P), r=0)
2017-07-17 15:44:51.294 [DEBUG] Read 4148 entries from profile archive (size: 101121157; compressed: 46520773)
2017-07-17 15:44:51.301 [INFO ] Completed DirectFlex import (41502 ms) [<<IFP#9485a7d3-1528da]

Dont know why this is. The share is on a 3Par all-flash system, takes a sec to copy 100MB otherwise.

[DEMdev]

Wow, that is rather slow, yes, particularly if it's on flash...

You mention that copying 100MB just takes a second, but how long does it take to "manually" copy these 4000+ files to and from your storage (there's always some overhead when copying lots of (small) files)?

Also, could this be caused by an anti-virus agent?

[Pim_van_de_Vis · Accepted solution]

I agree, it might be a good idea to implement these anti virus exclusions:

https://kb.vmware.com/kb/2113665

[pchapman]

I notice in your first post there is a 13 second delay after the regedit command.  I am currently diagnosing this in a customers environment.  We've seen up to 2 minutes 36 seconds for a single ImportRegistry command to run (even though the REG file in the profilearchive is only 5Kb). - Up to 10 minutes for a complete windows logon when you add them all up.  What are you running for anti-virus or anti-malware?  I think we have tracked it down to Cisco AMP for Endpoints but are still diagnosing.

2017-07-16 19:30:43.575 [DEBUG] ImportRegistry::Import: Calling '"C:\Windows\REGEDIT.EXE" /S "C:\Users\pewe\AppData\Local\Temp\FLX7776.tmp"' (RPAL: l=0 (D/P), r=0)

2017-07-16 19:30:56.323 [ERROR] ImportFiles::ImportFile: Access denied on 'LocalAppData/Packages/Microsoft.MicrosoftEdge_8wekyb3d8bbwe/AC/MicrosoftEdge/User/Default/DataStore/Data/nouser1/120712-0049/Favorites/16e930b2d0b35b_Icon.ico'

[DEMdev]

Hi pchapman​,

It's probably better to start a new thread on this, but just as a quick note:

2017-07-16 19:30:43.575 [DEBUG] ImportRegistry::Import: Calling '"C:\Windows\REGEDIT.EXE" /S "C:\Users\pewe\AppData\Local\Temp\FLX7776.tmp"' (RPAL: l=0 (D/P), r=0)

2017-07-16 19:30:56.323 [ERROR] ImportFiles::ImportFile: Access denied on 'LocalAppData/Packages/Microsoft.MicrosoftEdge_8wekyb3d8bbwe/AC/MicrosoftEdge/User/Default/DataStore/Data/nouser1/120712-0049/Favorites/16e930b2d0b35b_Icon.ico'

These two log lines do not necessarily mean that regedit took nearly 13s to run. After running regedit, the UEM agent starts importing the other files from the profile archive. As we don't log when regedit has finished, it may very well be the case that regedit ran very quickly and that the slowdown is caused by the subsequent file imports.

We'll improve this logging in a future version (not the upcoming one, but the one after that – not that I can provide release dates anyway 🙂 to at least provide info on how long the registry import took, and possibly try to provide some insight regarding slow file imports (although that will be harder to quantify).

For now, I'd recommend not to focus on the registry import, but on the subsequent imports of the other files in that profile archive. Typically such slowdowns are caused by antivirus or other endpoint security products, network or storage issues, or having UEM import and export files from locations for which folder redirection is configured.