Start a Conversation

This post is more than 5 years old

Solved!

Go to Solution

210228

October 10th, 2014 05:00

Slow logon because of errors with PNShell

Hi,

I'am experiencing a slow logon process caused bij pnshell when I logon to a VDI. The versions that I'm using are:

  •  Quest Instant Provisioning Service x64 8.0.306.1427
  • Quest Tools for the Managed Desktop (64-bit)

I've generated a logfile, see below. What can be the cause and what is the solution?

10-Oct-2014 10:49:55 - 4884 : 1116 - !===========================================================!
10-Oct-2014 10:49:55 - 4884 : 1116 - PnShell Log
10-Oct-2014 10:49:55 - 3408 : 1804 - !===========================================================!
10-Oct-2014 10:49:55 - 4884 : 1116 - User: [VDI-CL-TEST002\Administrator]
10-Oct-2014 10:49:55 - 3408 : 1804 - PnShell Log
10-Oct-2014 10:49:55 - 4884 : 1116 - Operating System Version: [6.2.9200]
10-Oct-2014 10:49:55 - 3408 : 1804 - User: [mydomain\VDI-CL-TEST002$]
10-Oct-2014 10:49:55 - 4884 : 1116 - Machine Name: [VDI-CL-TEST002.mydomain.local]
10-Oct-2014 10:49:55 - 3408 : 1804 - Operating System Version: [6.2.9200]
10-Oct-2014 10:49:55 - 4884 : 1116 - PnShell Version: [8.0.306.1427]
10-Oct-2014 10:49:55 - 3408 : 1804 - Machine Name: [VDI-CL-TEST002.mydomain.local]
10-Oct-2014 10:49:55 - 4884 : 1116 - Parent Process: [winlogon.exe]
10-Oct-2014 10:49:55 - 3408 : 1804 - PnShell Version: [8.0.306.1427]
10-Oct-2014 10:49:55 - 4884 : 1116 - !===========================================================!
10-Oct-2014 10:49:55 - 3408 : 1804 - Parent Process: [pnsenapp.exe]
10-Oct-2014 10:49:55 - 4884 : 1116 - PNShell.cpp - Not running as [SYSTEM] user. Running as [Administrator]
10-Oct-2014 10:49:55 - 3408 : 1804 - !===========================================================!
10-Oct-2014 10:49:55 - 4884 : 1116 - CShellConfigFile - ERROR: Could not open xml file! Xml file name: C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml
10-Oct-2014 10:49:55 - 3408 : 1804 - PNShell.cpp - We are running as the SYSTEM user.
10-Oct-2014 10:49:55 - 4884 : 1116 - PNShell.cpp - XML file was empty
10-Oct-2014 10:49:55 - 3408 : 1804 - CShellConfigFile - ERROR: Could not open xml file! Xml file name: C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml
10-Oct-2014 10:49:55 - 4884 : 1116 - PNShell - Successfully created event [PNSHELL_USERINIT_2]
10-Oct-2014 10:49:55 - 3408 : 1804 - PNShell - Successfully opened event [PNSHELL_USERINIT_2]
10-Oct-2014 10:49:55 - 4884 : 1116 - PNShell - Waiting on event [PNSHELL_USERINIT_2]
10-Oct-2014 10:49:55 - 3408 : 1804 - PNShell - Setting event [PNSHELL_USERINIT_2]
10-Oct-2014 10:49:55 - 4884 : 1116 - PNShell - Successfully created event [PNSHELL_COMPLETE_2]
10-Oct-2014 10:49:55 - 3408 : 4916 - CShellConfigFile - ERROR: Could not open xml file! Xml file name: C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old.
10-Oct-2014 10:49:55 - 4884 : 1116 - PNShell - Waiting on event [PNSHELL_COMPLETE_2]
10-Oct-2014 10:49:55 - 3408 : 4916 - PNShell.cpp - Reading contents of shell configuration file.
10-Oct-2014 10:49:55 - 3408 : 4916 - CShellConfigFile - ERROR: Could not open xml file! Xml file name: C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml
10-Oct-2014 10:49:55 - 3408 : 4916 - PNShell - Successfully opened event [PNSHELL_COMPLETE_2]
10-Oct-2014 10:49:55 - 3408 : 4916 - PNShell - Setting event [PNSHELL_COMPLETE_2]
10-Oct-2014 10:49:55 - 3408 : 4916 - PNShell - Successfully created event [PNSHELL_SESSION_COMPLETE_2]
10-Oct-2014 10:49:55 - 4884 : 1116 - Running USERINIT.EXE.
10-Oct-2014 10:49:55 - 3408 : 4916 - PNShell - Waiting on event [PNSHELL_SESSION_COMPLETE_2]
10-Oct-2014 10:49:55 - 4884 : 1116 - Launching [C:\WINDOWS\system32\USERINIT.EXE] as current user.
10-Oct-2014 10:50:11 - 4884 : 1116 - PNShell - ERROR: Failed to copy "C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml" to "C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.cleanshorts", error code = (3)
10-Oct-2014 10:50:11 - 4884 : 1116 - PNShell - ERROR: Failed to copy "C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old." to "C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old..cleanshorts", error code = (3)
10-Oct-2014 10:50:11 - 4884 : 1116 - PNShell - ERROR: Failed to copy "C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml" to "C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.netdrive", error code = (3)
10-Oct-2014 10:50:11 - 4884 : 1116 - PNShell - ERROR: Failed to copy "C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old." to "C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old..netdrive", error code = (3)
10-Oct-2014 10:50:11 - 4884 : 1116 - PNShell - ERROR: Failed to copy "C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml" to "C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.netprint", error code = (3)
10-Oct-2014 10:50:11 - 4668 : 4180 - Evaluating command line arguments.
10-Oct-2014 10:50:11 - 4460 : 4440 - Evaluating command line arguments.
10-Oct-2014 10:50:11 - 4884 : 1116 - PNShell - ERROR: Failed to copy "C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old." to "C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old..netprint", error code = (3)
10-Oct-2014 10:50:11 - 4668 : 4180 - PNShell - ParseCommandLineArgs2, args = ["/netdrive,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.netdrive,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old..netdrive"]
10-Oct-2014 10:50:11 - 4460 : 4440 - PNShell - ParseCommandLineArgs2, args = ["/cleanshorts,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.cleanshorts,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old..cleanshorts"]
10-Oct-2014 10:50:11 - 3408 : 1804 - WM_SETTINGCHANGE
10-Oct-2014 10:50:11 - 4884 : 1116 - PNShell - Successfully opened event [PNSHELL_SESSION_COMPLETE_2]
10-Oct-2014 10:50:11 - 4668 : 4180 - PNShell - ParseCommandLineArgs2, argv[0] = [/netdrive,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.netdrive,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old..netdrive]
10-Oct-2014 10:50:11 - 4464 : 4728 - Evaluating command line arguments.
10-Oct-2014 10:50:11 - 4460 : 4440 - PNShell - ParseCommandLineArgs2, argv[0] = [/cleanshorts,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.cleanshorts,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old..cleanshorts]
10-Oct-2014 10:50:11 - 4884 : 1116 - PNShell - Setting event [PNSHELL_SESSION_COMPLETE_2]
10-Oct-2014 10:50:11 - 4668 : 4180 - PNShell - Evaluating command line argument [/netdrive,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.netdrive,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old..netdrive]
10-Oct-2014 10:50:11 - 4464 : 4728 - PNShell - ParseCommandLineArgs2, args = ["/netprint,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.netprint,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old..netprint"]
10-Oct-2014 10:50:11 - 4460 : 4440 - PNShell - Evaluating command line argument [/cleanshorts,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.cleanshorts,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old..cleanshorts]
10-Oct-2014 10:50:11 - 3408 : 4916 - Failed to rename file [C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml] to [C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old.]. Error code [3]
10-Oct-2014 10:50:11 - 4668 : 4180 - CShellConfigFile - ERROR: Could not open xml file! Xml file name: C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.netdrive
10-Oct-2014 10:50:11 - 4464 : 4728 - PNShell - ParseCommandLineArgs2, argv[0] = [/netprint,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.netprint,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old..netprint]
10-Oct-2014 10:50:11 - 4460 : 4440 - CRegistryPerformer - Failed to query string value: Failed to open the "Software\Provision Networks\Manage-IT" key under HKCU: Het systeem kan het opgegeven bestand niet vinden.
10-Oct-2014 10:50:11 - 4668 : 4180 - NetworkDriveOperator.cpp - Unable to locate PNShell configuration file. Cannot configure network drives.
10-Oct-2014 10:50:11 - 4464 : 4728 - PNShell - Evaluating command line argument [/netprint,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.netprint,C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old..netprint]
10-Oct-2014 10:50:11 - 4460 : 4440 - CShortcutCleaner - Setting last run time to [Fri Oct 10 10:50:11 2014
]
10-Oct-2014 10:50:11 - 4464 : 4728 - NetworkPrinterOperator - Disconnecting existing printer connections.
10-Oct-2014 10:50:11 - 4460 : 4440 - Error opening registry key [Software\Provision Networks]
10-Oct-2014 10:50:11 - 4464 : 4728 - CShellConfigFile - ERROR: Could not open xml file! Xml file name: C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.old..netprint
10-Oct-2014 10:50:11 - 4460 : 4440 - CRegistryPerformer - Failed to write string value: Failed to open the "Software\Provision Networks\Manage-IT" key under HKCU: Het systeem kan het opgegeven bestand niet vinden.
10-Oct-2014 10:50:11 - 4464 : 4728 - NetworkPrinterOperator.cpp - Unable to locate PNShell configuration file. Cannot configure network printers.
10-Oct-2014 10:50:11 - 4460 : 4440 - CShortcutCleaner - Cleaning shortcuts created during first time login.
10-Oct-2014 10:50:11 - 4464 : 4728 - NetworkPrinterOperator - Connecting new printer connections.
10-Oct-2014 10:50:11 - 4460 : 4440 - CRegistryPerformer - Failed to delete value: Failed to delete the PnShell_Shortcuts value: Het systeem kan het opgegeven bestand niet vinden.
10-Oct-2014 10:50:11 - 4464 : 4728 - CShellConfigFile - ERROR: Could not open xml file! Xml file name: C:\ProgramData\Quest Software\vWorkspace\ShellResources.xml.netprint
10-Oct-2014 10:50:11 - 4460 : 4440 - CShortcutCleaner - Directory [C:\Users\Administrator\AppData\Local\Quest Software\vWorkspace\] does not exist. Cannot clean existing shortcuts.
10-Oct-2014 10:50:11 - 4464 : 4728 - NetworkPrinterOperator.cpp - Unable to locate PNShell configuration file. Cannot configure network printers.

October 16th, 2014 07:00

Hi All,

We've found that if you're not using Metaprofiles in your environment, you can save a fair few seconds off of your login time by not installing the User Profiles part of PNTools into your master image.

We did this here and it made a big difference.

Thanks, Andrew

15 Posts

October 10th, 2014 07:00

If you follow the timestamps, you'll notice that there is a 16-second gap after the line

10-Oct-2014 10:49:55 - 4884 : 1116 - Launching [C:\WINDOWS\system32\USERINIT.EXE] as current user.

This indicates that your Userinit is taking a while to run. PNShell has to wait for this process to complete before it can move on to applying the various assigned resources, since they require the user to be fully logged in. Before this point, PNShell could work as SYSTEM, but certain things are user-only.

There are a great number of reasons why Userinit might be taking so long, the majority of which are outside the scope of this log.

October 10th, 2014 08:00

When I replace the Userinit under HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Winlogon from C:\Program Files (x86)\Quest Software\PNTools\pnshell\pnShell.exe, to C:\Windows\system32\userinit.exe, and uninstall all the mentioned Quest software the 16 second gap is gone a new user does not see a black screen for 16 seconds after which the Start Screen is shown.

So my conclusions is that it's not the default Userinit but the pnShell.exe that is slowing down my logins.

October 11th, 2014 12:00

Just did some basic testing. The test was what is the time from the moment you press enter when you have entered your password until the start screen. My test involves a Windows 8 Enterprise and Windows 8.1 Enterprise domain joined VM placed in a IU with block inheritance from all GPO's.

The result are quit shocking in my opinion. The time it takes from pressing enter until the Start Screen WITHOUT pntools installed is less than a second, WITH pntools installed it is between 13 and 16 seconds.

I check the log and it the main difference is in this section:

  • Launching [C:\WINDOWS\system32\USERINIT.EXE] as current user.
  • WM_SETTINGCHANGE

Why is this and how do I resolve it?

25 Posts

October 13th, 2014 04:00

Hi Maarten - We have received your Service Request just raised with us through the support portal - one of my engineers will be back in touch with you to continue working with you on this.

Thanks

Kevin Robinson

Support Manager

No Events found!

Top