Performance issues and odd behaviour?

Feb 3, 2014 at 9:32 PM
Setup:
I have a Rackspace cloud account with several domain connected virtual machines. My local network is connected to this cloud network via a site-to-site vpn. I'm trying to automate bringing these systems online and into the domain and thought boxstarter might be a great way to bootstrap them before my other tools take over. I've run in to a few odd issues, though.

So Far:
I use psexec to remotely enable powershell remoting and set the executionpolicy to unrestricted. That works great and I can remote in with no issue. However, the first time I try to run boxstarter on the host, I get a strange error:
Install-BoxstarterPackage -Session $remotesession -Credential $cred -PackageName notepadplusplus -Verbose

Boxstarter Version 2.3.24
(c) 2014 Matt Wrock. http://boxstarter.org

Boxstarter: Copying Boxstarter Modules and local repo packages at C:\Users\dmurawsky.POLARIS\AppData\Roaming\Boxstarter to C:\Users\DMURAW~1.POL\AppData\Local\Temp on 10.183.15.27...
[TEST01]Boxstarter: Installing package notepadplusplus
[TEST01]Boxstarter: Disabling Automatic Updates from Windows Update
[TEST01]Boxstarter: Chocolatey not instaled. Downloading and installing...


Errors       : {The term 'C:\Users\ADMINI~1\AppData\Local\Temp\chocolatey\chocInstall\tools\chocolateyInstall.ps1' is not recognized as the name of a cmdlet, 
               function, script file, or operable program. Check the spelling of the name, or if a path was included, verify that the path is correct and try again.}
ComputerName : 10.183.15.27
Completed    : False
FinishTime   : 2/3/2014 4:16:57 PM
StartTime    : 2/3/2014 4:16:15 PM
It looks like a fatal error, but then I run the command again and it seems to start up.
Boxstarter: Copying Boxstarter Modules and local repo packages at C:\Users\dmurawsky.POLARIS\AppData\Roaming\Boxstarter to C:\Users\DMURAW~1.POL\AppData\Local\Temp on 10.183.15.27...
[TEST01]Boxstarter: Installing package notepadplusplus
[TEST01]Boxstarter: Disabling Automatic Updates from Windows Update
[TEST01]Boxstarter: Chocolatey not instaled. Downloading and installing...
[TEST01]+ Boxstarter starting Calling Chocolatey to install notepadplusplus. This may take several minutes to complete...
Chocolatey (v0.9.8.23) is installing 'notepadplusplus' and dependencies. By installing you accept the license for 'notepadplusplus' and each dependency you are installing.
______ notepadplusplus.install v6.5.3 ______
Downloading notepadplusplus 32 bit (http://download.tuxfamily.org/notepadplus/6.5.3/npp.6.5.3.Installer.exe) to C:\Users\ADMINI~1\AppData\Local\Temp\chocolatey\notepadplusplus\notepadplusplusInstall.exe
Now it's just taking forever to download the notepadplusplus package. When I do this locally on the server, it takes no time at all. At a guess, it looks like the package is downloading to my local machine and then pushing out to the server.... but that can't be right, can it?

If it makes a difference, I'm using the powergui scripting editor.
Thanks,
-D
Feb 3, 2014 at 9:37 PM
Update: once the download of notepad finished, it errored on the install:
C:\Users\dmurawsky.POLARIS\Documents> configure-server -Server $ServerIP -UserName $UserName -Password $Password
Boxstarter Version 2.3.24
(c) 2014 Matt Wrock. http://boxstarter.org

Boxstarter: Copying Boxstarter Modules and local repo packages at C:\Users\dmurawsky.POLARIS\AppData\Roaming\Boxstarter to C:\Users\DMURAW~1.POL\AppData\Local\Temp on 10.183.15.27...
[TEST01]Boxstarter: Installing package notepadplusplus
[TEST01]Boxstarter: Disabling Automatic Updates from Windows Update
[TEST01]Boxstarter: Chocolatey not instaled. Downloading and installing...
[TEST01]+ Boxstarter starting Calling Chocolatey to install notepadplusplus. This may take several minutes to complete...
Chocolatey (v0.9.8.23) is installing 'notepadplusplus' and dependencies. By installing you accept the license for 'notepadplusplus' and each dependency you are installing.
______ notepadplusplus.install v6.5.3 ______
Downloading notepadplusplus 32 bit (http://download.tuxfamily.org/notepadplus/6.5.3/npp.6.5.3.Installer.exe) to C:\Users\ADMINI~1\AppData\Local\Temp\chocolatey\notepadplusplus\notepadplusplusInstall.exe
notepadplusplus did not finish successfully. Boo to the chocolatey gods!
-----------------------
[ERROR] Exception calling "Read" with "3" argument(s): "The operation has timed out."
-----------------------
    + CategoryInfo          : NotSpecified: (:) [Write-Error], WriteErrorException
    + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,Write-Error
    + PSComputerName        : 10.183.15.27
 
Package 'notepadplusplus.install v6.5.3' did not install successfully: Exception calling "Read" with "3" argument(s): "The operation has timed out."
    + CategoryInfo          : NotSpecified: (:) [Write-Error], WriteErrorException
    + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,Write-Error
    + PSComputerName        : 10.183.15.27
 
______ notepadplusplus v6.5.3 ______
Finished installing 'notepadplusplus' and dependencies - if errors not shown in console, none detected. Check log for errors if unsure.
[TEST01]+ Boxstarter finished Calling Chocolatey to install notepadplusplus. This may take several minutes to complete... 00:17:40.2433904
[TEST01]Boxstarter: Enabling Automatic Updates from Windows Update


Errors       : {Package 'notepadplusplus.install v6.5.3' did not install successfully: Exception calling "Read" with "3" argument(s): "The operation has timed 
               out.", notepadplusplus did not finish successfully. Boo to the chocolatey gods!
               -----------------------
               [ERROR] Exception calling "Read" with "3" argument(s): "The operation has timed out."
               -----------------------}
ComputerName : 10.183.15.27
Completed    : True
FinishTime   : 2/3/2014 4:36:13 PM
StartTime    : 2/3/2014 4:18:17 PM

Coordinator
Feb 4, 2014 at 3:50 PM
Hi there and thanks for posting this.

This all does seem curious and I have a very loose theory.

The first problem is occuring in the Chocolatey installer. Boxstarter downloads the chocolatey installer and then that installer downloads the chocolatey package to %temp%\chocolatey\ChocInstall and then it downloads 7zip to unzip that package. The unzipping extracts the file that the first error complains about.

My guess is that this error is also perf related. I'd bet there is a race condition at play here where the extraction is not complete by the time it tries to execute the extracted script. One thing you could do to help troubleshoot is add the -Verbose parameter to the Install-BoxstarterPackage command. That may print out some extra information about what is going on there.

Regarding the Notepad++ install, it is downloaded on the VM and not locally but I can see how it looks otherwise. You mentioned it downloads much more quickly when you perform the download locally. When doing it locally do you download via chocolatey or from the notepad++ web site? Knowing that would help determine if it is a chocolatey issue or not.
Feb 4, 2014 at 4:48 PM
Thanks for the reply!

The local install was done through chocolatey and worked well/quickly. The remote install was also done with the chocolatey package, but using boxstarter to wrap it as in the command above.

Here is a full walkthrough of my script/setup. I'm running the commands manually as I type this, outside of the functions and other wrappers that I've created, to ensure that my code isn't borking it somehow.

I use psexec to "enable-psremoting -force" & "set-executionpolicy unrestricted -force" & "Enable-WSMaCredSSP -Role Server –Force" on the target server.

The script imports the boxstarter module using Import-Module Boxstarter.Chocolatey

The script creates a credential object.
$mycred = new-object -typename System.Management.Automation.PSCredential -argumentlist $UserName,(ConvertTo-SecureString $Password -asplaintext -force)
The script creates a session object using the credential object.
$remotesession = New-PSSession $Server -Credential $mycred
I confirm the session works by entering the PS session and running hostname.

The script then tries to install notepadplusplus using boxstarter
Install-BoxstarterPackage -Session $remotesession -PackageName notepadplusplus -Verbose 
The output is as follows
C:\> Install-BoxstarterPackage -Session $remotesession -PackageName notepadplusplus -Verbose
Boxstarter Version 2.3.24
(c) 2014 Matt Wrock. http://boxstarter.org

VERBOSE: Boxstarter: Processing Session...
VERBOSE: Boxstarter: Attempt #1 to copy Boxstarter modules to 10.183.133.138
Boxstarter: Copying Boxstarter Modules and local repo packages at C:\Users\dmurawsky.POLARIS\AppData\Roaming\Boxstarter
to C:\Users\DMURAW~1.POL\AppData\Local\Temp on 10.183.133.138...
VERBOSE: Loading module from path
'C:\Users\ADMINI~1\AppData\Local\Temp\Boxstarter\Boxstarter.Chocolatey\Boxstarter.Chocolatey.psd1'.
VERBOSE: Importing function 'Enable-BoxstarterClientRemoting'.
VERBOSE: Importing function 'Enable-BoxstarterCredSSP'.
VERBOSE: Importing function 'Get-BoxStarterConfig'.
VERBOSE: Importing function 'Get-PackageRoot'.
VERBOSE: Importing function 'Install-BoxstarterPackage'.
VERBOSE: Importing function 'Install-ChocolateyInstallPackageOverride'.
VERBOSE: Importing function 'Invoke-BoxStarterBuild'.
VERBOSE: Importing function 'Invoke-ChocolateyBoxstarter'.
VERBOSE: Importing function 'New-BoxstarterPackage'.
VERBOSE: Importing function 'New-PackageFromScript'.
VERBOSE: Importing function 'Resolve-VMPlugin'.
VERBOSE: Importing function 'Set-BoxStarterConfig'.
VERBOSE: Importing function 'Set-BoxstarterShare'.
VERBOSE: Importing function 'Write-HostOverride'.
VERBOSE: Importing alias 'Enable-BoxstarterVM'.
VERBOSE: Importing alias 'Install-ChocolateyInstallPackage'.
VERBOSE: Importing alias 'Write-Host'.
[TEST02]Boxstarter: Installing package notepadplusplus
VERBOSE: [TEST02]+ Boxstarter starting Installation session.
VERBOSE: [TEST02]Boxstarter: NoPassword is false checking autologin
VERBOSE: [TEST02]Boxstarter: AutoLogin status is True
VERBOSE: [TEST02]Boxstarter: NoPassword is set to True and rebootok is set to True and the nopassword param passed was
False
[TEST02]Boxstarter: Disabling Automatic Updates from Windows Update
VERBOSE: Loading module from path
'C:\Users\Administrator\AppData\Local\Temp\Boxstarter\BoxStarter.Chocolatey\Boxstarter.Chocolatey.psd1'.
VERBOSE: Importing function 'Enable-BoxstarterClientRemoting'.
VERBOSE: Importing function 'Enable-BoxstarterCredSSP'.
VERBOSE: Importing function 'Get-BoxStarterConfig'.
VERBOSE: Importing function 'Get-PackageRoot'.
VERBOSE: Importing function 'Install-BoxstarterPackage'.
VERBOSE: Importing function 'Install-ChocolateyInstallPackageOverride'.
VERBOSE: Importing function 'Invoke-BoxStarterBuild'.
VERBOSE: Importing function 'Invoke-ChocolateyBoxstarter'.
VERBOSE: Importing function 'New-BoxstarterPackage'.
VERBOSE: Importing function 'New-PackageFromScript'.
VERBOSE: Importing function 'Resolve-VMPlugin'.
VERBOSE: Importing function 'Set-BoxStarterConfig'.
VERBOSE: Importing function 'Set-BoxstarterShare'.
VERBOSE: Importing function 'Write-HostOverride'.
VERBOSE: Importing alias 'Enable-BoxstarterVM'.
VERBOSE: Importing alias 'Install-ChocolateyInstallPackage'.
VERBOSE: Importing alias 'Write-Host'.
VERBOSE: [TEST02]Boxstarter: LocalRepo is at C:\Users\Administrator\AppData\Local\Temp\Boxstarter\BuildPackages
[TEST02]Boxstarter: Chocolatey not instaled. Downloading and installing...
VERBOSE: [TEST02]Boxstarter: Downloading http://chocolatey.org/install.ps1 to
C:\Users\ADMINI~1\AppData\Local\Temp\choco.ps1
VERBOSE: [TEST02]Boxstarter: Attempt #1...
chocInstall
Downloading http://chocolatey.org/api/v2/package/chocolatey/ to C:\Users\ADMINI~1\AppData\Local\Temp\chocolatey\chocInst
all\chocolatey.zip
Download 7Zip commandline tool
Downloading https://github.com/chocolatey/chocolatey/blob/master/src/tools/7za.exe?raw=true to C:\Users\ADMINI~1\AppData
\Local\Temp\chocolatey\chocInstall\7za.exe
Extracting C:\Users\ADMINI~1\AppData\Local\Temp\chocolatey\chocInstall\chocolatey.zip to C:\Users\ADMINI~1\AppData\Local
\Temp\chocolatey\chocInstall...
Installing chocolatey on this machine
VERBOSE: [TEST02]Boxstarter: Removing Boxstarter Scheduled Task...
VERBOSE: [TEST02]Boxstarter: Removed Boxstarter Scheduled Task with this result: SUCCESS: The scheduled task
"Boxstarter Task" was successfully deleted.
[TEST02]Boxstarter: Enabling Automatic Updates from Windows Update
VERBOSE: [TEST02]+ Boxstarter finished Installation session. 00:00:22.4009892
VERBOSE: Boxstarter: checking if session should be removed...
VERBOSE: Boxstarter: Composing record for pipeline...
VERBOSE: Boxstarter: writing object...


Errors       : {The term 'C:\Users\ADMINI~1\AppData\Local\Temp\chocolatey\chocInstall\tools\chocolateyInstall.ps1' is
               not recognized as the name of a cmdlet, function, script file, or operable program. Check the spelling
               of the name, or if a path was included, verify that the path is correct and try again.}
ComputerName : 10.183.133.138
Completed    : False
FinishTime   : 2/4/2014 11:39:55 AM
StartTime    : 2/4/2014 11:39:25 AM

VERBOSE: Boxstarter: object written...
I then rentered the session to see what's up on the server. The chocolatey directory is present, but empty.

I thought this might be the fact that I'm not using authentication credssp. When I try to do that with the following command, I get an error.
C:\> $remotesession = New-PSSession $ServerIP -Credential $mycred -Authentication Credssp
New-PSSession : [10.183.133.138] Connecting to remote server 10.183.133.138 failed with the following error message :
The WinRM client cannot process the request. A computer policy does not allow the delegation of the user credentials
to the target computer because the computer is not trusted. The identity of the target computer can be verified if you
configure the WSMAN service to use a valid certificate using the following command: winrm set winrm/config/service
'@{CertificateThumbprint="<thumbprint>"}'  Or you can check the Event Viewer for an event that specifies that the
following SPN could not be created: WSMAN/<computerFQDN>. If you find this event, you can manually create the SPN
using setspn.exe .  If the SPN exists, but CredSSP cannot use Kerberos to validate the identity of the target computer
and you still want to allow the delegation of the user credentials to the target computer, use gpedit.msc and look at
the following policy: Computer Configuration -> Administrative Templates -> System -> Credentials Delegation -> Allow
Fresh Credentials with NTLM-only Server Authentication.  Verify that it is enabled and configured with an SPN
appropriate for the target computer. For example, for a target computer name "myserver.domain.com", the SPN can be one
of the following: WSMAN/myserver.domain.com or WSMAN/*.domain.com. Try the request again after these changes. For more
information, see the about_Remote_Troubleshooting Help topic.
At line:1 char:18
+ $remotesession = New-PSSession $ServerIP -Credential $mycred -Authentication Cre ...
+                  ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : OpenError: (System.Manageme....RemoteRunspace:RemoteRunspace) [New-PSSession], PSRemotin
   gTransportException
    + FullyQualifiedErrorId : -2144108124,PSSessionOpenFailed
C:\>
So that's where I am. Please let me know if I can provide any other information to assist with debugging, and thank you for taking the time to do so.
-D
Feb 4, 2014 at 5:52 PM
By using gpedit and adding * to the credSSP configurations in the local policy, I was able to get this to work. No more errors appearing. Very odd. I tried this before and it was failing for several reasons, hence the complicated workaround I was trying...

I'm going to try a few more times with new virtual machines to see if I can figure out the details of what's going on. I will update if I find anything useful out.
-D
Coordinator
Feb 4, 2014 at 6:12 PM
I haven't fully digested the last couple messages but wanted to quickly reply with a suggestion. Instead of newing up a session on your own, try:
Install-BoxstarterPackage -ComputerName $server -Credential $credential -PackageName notepadplusplus -Verbose
While passing in a session is obviously supported, I'll admit that I do most of my own testing using computername. This way Boxstarter creates the session and it also sets up CredSSP taking care of all the gpedit stuff so it should eliminate some of the grunt work you have to do to get that working. That said, I'm not convinced at all that CredSSP is the problem. However, there may be some other issue in the logic when using its own session that could be at play.

Another questin is what VM platform are you using. If it is Hyper-V or an Azure VM, you can eliminate the PSExec call by using the Enable-BoxstarterVM command.

I'll look closer at this tonight and do some testing using a self made session to see if I can reproduce.
Coordinator
Feb 5, 2014 at 8:39 AM
So one possibility is that there may be proxy issues preventing the initial chocolatey download. In fact this could also explain why CredSSP fixes things in your case. The Chocolatey Bootstrapper does not set any proxy settings. Its possible that the web request causes the proxy to prompt for credentials. Since this is a remote powershell session, you wont get the prompt. Also without CredSSP your current credentials cant make the "second hop" to auth against the proxy. so the choco bits do not get downloaded. It is odd however that it works on the second attempt.

BTW: I did test with a prebuilt session without credssp and did not run into any issues however, I dont have a proxy that I need to authenticate with. Do you know if you have a proxy in your environment?