Skip to content
This repository has been archived by the owner on Jun 14, 2024. It is now read-only.

MSFT_MsiPackage.Integration.Tests.ps1: Tests fail with: RuntimeException: The variable '$responseStream' cannot be retrieved because it has not been set #142

Closed
mhendric opened this issue Apr 22, 2019 · 3 comments · Fixed by #143, #157 or dsccommunity/xPSDesiredStateConfiguration#627
Assignees
Labels
bug The issue is a bug. in progress The issue is being actively worked on by someone.

Comments

@mhendric
Copy link
Contributor

Details of the scenario you tried and the problem that is occurring

I'm not sure what the full set of conditions that cause this are, but tests have been failing lately in MSFT_MsiPackage.Integration.Tests.ps1 with the below error when trying to connect to a local HTTPS endpoint. It appears that this occurs at least in part when [Net.ServicePointManager]::SecurityProtocol is set to: Ssl3, Tls. The fix appears to be to set SchUseStrongCrypto to 1 on the test machine, which changes [Net.ServicePointManager]::SecurityProtocol to Tls, Tls11, Tls12.

Verbose logs showing the problem

[00:14:42] Executing script C:\projects\psdscresources\Tests\Integration\MSFT_MsiPackage.Integration.Tests.ps1
[00:14:43] 
[00:14:43]   Describing MSFT_MsiPackage Integration Tests
[00:14:44] 
[00:14:44]     Context Get-TargetResource
[00:14:44]       [+] Should return only basic properties for absent package 403ms
[00:14:45]       [+] Should return full package properties for present package without registry check parameters specified 1.16s
[00:14:45] 
[00:14:45]     Context Test-TargetResource
[00:14:48]       [+] Should return correct value when package is absent 2.36s
[00:14:49]       [+] Should return correct value when package is present 800ms
[00:14:49] 
[00:14:49]     Context Set-TargetResource
[00:14:52]       [+] Should correctly install and remove a .msi package 3.11s
[00:14:52]       [+] Should throw with incorrect product id 318ms
[00:14:56]       [+] Should correctly install and remove a package from a HTTP URL 3.41s
[00:15:28]       [-] Should correctly install and remove a package from a HTTPS URL 32.54s
[00:15:28]         RuntimeException: The variable '$responseStream' cannot be retrieved because it has not been set.
[00:15:28]         at Set-TargetResource, C:\projects\psdscresources\DSCResources\MSFT_MsiPackage\MSFT_MsiPackage.psm1: line 262
[00:15:28]         at <ScriptBlock>, C:\projects\psdscresources\Tests\Integration\MSFT_MsiPackage.Integration.Tests.ps1: line 230
[00:15:29]       [+] Should write to the specified log path 801ms
[00:15:33]       [+] Should add space after .MSI installation arguments 3.51s
[00:15:33]       [+] Should not check for product installation when rebooted is required 513ms
[00:15:34]       [+] Should install package using user credentials when specified 534ms

Suggested solution to the issue

On test machines, set the following keys before executing MsiPackage tests:

Set-ItemProperty -Path 'HKLM:\SOFTWARE\Wow6432Node\Microsoft.NetFramework\v4.0.30319' -Name 'SchUseStrongCrypto' -Value '1' -Type DWord -ErrorAction Stop
Set-ItemProperty -Path 'HKLM:\SOFTWARE\Microsoft.NetFramework\v4.0.30319' -Name 'SchUseStrongCrypto' -Value '1' -Type DWord -ErrorAction Stop

The operating system the target node is running

OsName : Microsoft Windows Server 2019 Standard
OsOperatingSystemSKU : StandardServerEdition
OsArchitecture : 64-bit
WindowsVersion : 1809
WindowsBuildLabEx : 17763.1.amd64fre.rs5_release.180914-1434
OsLanguage : en-US
OsMuiLanguages : {en-US}

Version and build of PowerShell the target node is running

PS C:> $PSVersionTable

Name Value


PSVersion 5.1.17763.316
PSEdition Desktop
PSCompatibleVersions {1.0, 2.0, 3.0, 4.0...}
BuildVersion 10.0.17763.316
CLRVersion 4.0.30319.42000
WSManStackVersion 3.0
PSRemotingProtocolVersion 2.3
SerializationVersion 1.1.0.1

Version of the DSC module that was used ('dev' if using current dev branch)

dev

@mhendric
Copy link
Contributor Author

Re-opening issue. #143 did not fix this after all (see #154).

@mhendric mhendric added bug The issue is a bug. in progress The issue is being actively worked on by someone. labels May 25, 2019
@mhendric
Copy link
Contributor Author

Adding some more troubleshooting info, since it turned out that my theory on Strong Crypto being the problem was wrong. After digging deeper, it turns out that the following error message is really just a result of the test machine being in Strict mode for PowerShell:

RuntimeException: The variable '$responseStream' cannot be retrieved because it has not been set.

Specifically this occurs in MSFT_MsiPackage\MSFT_MsiPackage.psm1\Set-TargetResource when a null responseStream is returned from Get-WebRequestResponse. This particular error can be avoided by using Test-Path to see if the responseStream variable is null.

After fixing the above and adding some additional logging, I found another problem in Tests\TestHelpers\MSFT_MsiPackageResource.TestHelper.psm1\Start-Server, which is used to create an HTTP(S) server to host a test MsiPackage. A major problem in this function is that it starts and runs the HTTP(S) server within a PowerShell Job, and that it doesn't check to see if the job encountered errors or exceptions before signaling to the client that the server is setup correctly. Further, if an exception was encountered in the job, it would not be bubbled up to the calling code. A future fix for this issue should include bubbling up any underlying failures in the PowerShell job so that we can fail quicker, and also see why we failed.

With the above logging and exception raising in place, I found that this was an underlying error being encountered when trying to start the HTTPListener in Start-Server:

There were problems setting up the HTTP(s) listener. Error: Exception calling "Start" with "0" argument(s): "The process cannot access the file because it is being used by another process"

And with the $responseStream issue addressed above, I could see that Set-TargetResource was failing with:

[00:11:51]       [-] Should correctly install and remove a package from a HTTPS URL 32.43s
[00:11:52]         Exception: System.InvalidOperationException: An error occurred while trying to get the https response for file https://localhost:1243/package.msi ---> System.Management.Automation.MethodInvocationException: Exception calling "GetResponse" with "0" argument(s): "Unable to connect to the remote server" ---> System.Net.WebException: Unable to connect to the remote server ---> System.Net.Sockets.SocketException: No connection could be made because the target machine actively refused it 127.0.0.1:1243
[00:11:52]            at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress)
[00:11:52]            at System.Net.ServicePoint.ConnectSocketInternal(Boolean connectFailure, Socket s4, Socket s6, Socket& socket, IPAddress& address, ConnectSocketState state, IAsyncResult asyncResult, Exception& exception)
[00:11:52]            --- End of inner exception stack trace ---
[00:11:52]            at System.Net.HttpWebRequest.GetResponse()
[00:11:52]            at CallSite.Target(Closure , CallSite , HttpWebRequest )
[00:11:52]            --- End of inner exception stack trace ---
[00:11:52]            at System.Management.Automation.ExceptionHandlingOps.CheckActionPreference(FunctionContext funcContext, Exception exception)
[00:11:52]            at System.Management.Automation.Interpreter.ActionCallInstruction`2.Run(InterpretedFrame frame)
[00:11:52]            at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)
[00:11:52]            at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)
[00:11:52]            at System.Management.Automation.Interpreter.Interpreter.Run(InterpretedFrame frame)
[00:11:52]            at System.Management.Automation.Interpreter.LightLambda.RunVoid1[T0](T0 arg0)
[00:11:52]            at System.Management.Automation.PSScriptCmdlet.RunClause(Action`1 clause, Object dollarUnderbar, Object inputToProcess)
[00:11:52]            at System.Management.Automation.PSScriptCmdlet.DoEndProcessing()
[00:11:52]            at System.Management.Automation.CommandProcessorBase.Complete()
[00:11:52]            --- End of inner exception stack trace ---
[00:11:52]         at New-InvalidOperationException, C:\projects\psdscresources\DSCResources\CommonResourceHelper.psm1: line 137
[00:11:52]         at Get-WebRequestResponse, C:\projects\psdscresources\DSCResources\MSFT_MsiPackage\MSFT_MsiPackage.psm1: line 806
[00:11:52]         at Set-TargetResource, C:\projects\psdscresources\DSCResources\MSFT_MsiPackage\MSFT_MsiPackage.psm1: line 266
[00:11:52]         at <ScriptBlock>, C:\projects\psdscresources\Tests\Integration\MSFT_MsiPackage.Integration.Tests.ps1: line 263

So in this case, the HTTPListener failed to setup properly because there was a lock on the test file, and then Set-TargetResource failed to connect to the HTTP server. I believe this particular problem can be avoided by ensuring that all test HTTP(S) jobs are fully closed and removed before trying to setup new jobs.

A new fix for all of this should be getting submitted very soon.

@mhendric
Copy link
Contributor Author

Adding some more troubleshooting info. I had last suspected that this issue was being caused because the PowerShell jobs that run the HTTP Listener were being left open. However, I added code to ensure that jobs were being closed, and I still encountered this. I then added some additional logging around where the error occurs, and found that the AppVeyor build agent was running on port 1243 (the same port the HttpListener is trying to register on). I also found that WmiPrvSE likes to snag ports in the 1230 - 1240 range, so plausibly could conflict with 1243 at some point as well. Given all this, my next attempt at a fix will be to move these HttpListeners to a much higher port number (thinking of picking a high number, unassigned port in here: https://www.iana.org/assignments/service-names-port-numbers/service-names-port-numbers.xhtml?&page=130)

[00:12:17] VERBOSE: Running Process Info
[00:12:17] VERBOSE: 
[00:12:17] VERBOSE: Handles  NPM(K)    PM(K)      WS(K)     CPU(s)     Id  SI ProcessName                                                                                                                                                                
[00:12:17] VERBOSE: -------  ------    -----      -----     ------     --  -- -----------                                                                                                                                                                
[00:12:17] VERBOSE:    1595      98   517480     491728     266.98   2928   1 Appveyor.BuildAgent.Interactive                                                                                                                                            
[00:12:17] VERBOSE:      48       5     1588       4204       0.02   1288   1 conhost                                                                                                                                                                    
[00:12:17] VERBOSE:      59       7     1076       4324       0.05   2496   1 conhost                                                                                                                                                                    
[00:12:17] VERBOSE:     188      11     1740       3832       0.08    372   0 csrss                                                                                                                                                                      
[00:12:17] VERBOSE:     158      11     1412       7404       0.20    432   1 csrss                                                                                                                                                                      
[00:12:17] VERBOSE:     108       7     1212       5008       0.00   2480   1 dllhost                                                                                                                                                                    
[00:12:17] VERBOSE:     179      16    14076      23524       0.13    712   1 dwm                                                                                                                                                                        
[00:12:17] VERBOSE:    1076      53    31060      68532       1.03   2228   1 explorer                                                                                                                                                                   
[00:12:17] VERBOSE:       0       0        0          4                 0   0 Idle                                                                                                                                                                       
[00:12:17] VERBOSE:     841      19     4580      12044       1.75    524   0 lsass                                                                                                                                                                      
[00:12:17] VERBOSE:     159      12     2484       7048       0.02   1032   0 msdtc                                                                                                                                                                      
[00:12:17] VERBOSE:     213      12     7580      12024       1.98   2732   0 msiexec                                                                                                                                                                    
[00:12:17] VERBOSE:     617      31   165320     189360       1.25    596   1 powershell                                                                                                                                                                 
[00:12:17] VERBOSE:     211      10     2280       5460       0.31    516   0 services                                                                                                                                                                   
[00:12:17] VERBOSE:      52       3      296       1036       0.09    268   0 smss                                                                                                                                                                       
[00:12:17] VERBOSE:     112      10     3336       7924       0.05    564   0 svchost                                                                                                                                                                    
[00:12:17] VERBOSE:     114      11     1648       5064       0.06    568   0 svchost                                                                                                                                                                    
[00:12:17] VERBOSE:     373      16     3600       9816       0.14    588   0 svchost                                                                                                                                                                    
[00:12:17] VERBOSE:     186      13     2992       9732       0.02    612   0 svchost                                                                                                                                                                    
[00:12:17] VERBOSE:     335      15     2812       6204       0.33    620   0 svchost                                                                                                                                                                    
[00:12:17] VERBOSE:     504      20    13164      16796       0.81    720   0 svchost                                                                                                                                                                    
[00:12:17] VERBOSE:    1450      46    15940      30848       2.61    748   0 svchost                                                                                                                                                                    
[00:12:17] VERBOSE:     415      21     4776       9920       0.09    804   0 svchost                                                                                                                                                                    
[00:12:17] VERBOSE:     802      37    11384      22464       1.00    872   0 svchost                                                                                                                                                                    
[00:12:17] VERBOSE:     400      34     7772      13284       0.33    988   0 svchost                                                                                                                                                                    
[00:12:17] VERBOSE:     382      26     9964      18180       1.33   1088   0 svchost                                                                                                                                                                    
[00:12:17] VERBOSE:     472      21     4052       9048       0.09   1264   0 svchost                                                                                                                                                                    
[00:12:17] VERBOSE:     258      15     2684       7744       0.19   1488   0 svchost                                                                                                                                                                    
[00:12:17] VERBOSE:      82       6      844       3948       0.00   2392   0 svchost                                                                                                                                                                    
[00:12:17] VERBOSE:     610       0      104        268      11.77      4   0 System                                                                                                                                                                     
[00:12:17] VERBOSE:     121       9     1460       6128       0.03   1636   0 VSSVC                                                                                                                                                                      
[00:12:17] VERBOSE:      80       8      780       3896       0.03    424   0 wininit                                                                                                                                                                    
[00:12:17] VERBOSE:     149       8     1360       6248       0.05    460   1 winlogon                                                                                                                                                                   
[00:12:17] VERBOSE:     365      15     6368      14608       0.53   1908   0 WmiPrvSE                                                                                                                                                                   
[00:12:17] VERBOSE:     938      50    97356     124776       9.48   1964   0 WmiPrvSE                                                                                                                                                                   
[00:12:17] VERBOSE: 
[00:12:17] VERBOSE: 
[00:12:17] VERBOSE: 
[00:12:17] VERBOSE: Open TCP Connections Info
[00:12:17] VERBOSE: 
[00:12:17] VERBOSE: LocalAddress                        LocalPort RemoteAddress                       RemotePort State       AppliedSetting OwningProcess 
[00:12:17] VERBOSE: ------------                        --------- -------------                       ---------- -----       -------------- ------------- 
[00:12:17] VERBOSE: ::                                  1243      ::                                  0          Bound                      2928          
[00:12:17] VERBOSE: ::                                  1240      ::                                  0          Bound                      1964          
[00:12:17] VERBOSE: ::                                  1237      ::                                  0          Bound                      1964          
[00:12:17] VERBOSE: ::                                  47001     ::                                  0          Listen                     4             
[00:12:17] VERBOSE: ::                                  5985      ::                                  0          Listen                     4             
[00:12:17] VERBOSE: ::                                  3389      ::                                  0          Listen                     1264          
[00:12:17] VERBOSE: ::1                                 1241      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::1                                 1239      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::1                                 1238      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::1                                 1236      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::                                  1235      ::                                  0          Listen                     568           
[00:12:17] VERBOSE: ::1                                 1234      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::1                                 1233      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::1                                 1232      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::1                                 1231      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::1                                 1230      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::1                                 1229      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::1                                 1227      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::1                                 1226      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::1                                 1225      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::1                                 1224      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::1                                 1223      ::1                                 5985       TimeWait                   0             
[00:12:17] VERBOSE: ::                                  1033      ::                                  0          Listen                     4             
[00:12:17] VERBOSE: ::                                  1029      ::                                  0          Listen                     524           
[00:12:17] VERBOSE: ::                                  1028      ::                                  0          Listen                     516           
[00:12:17] VERBOSE: ::                                  1027      ::                                  0          Listen                     748           
[00:12:17] VERBOSE: ::                                  1026      ::                                  0          Listen                     720           
[00:12:17] VERBOSE: ::                                  1025      ::                                  0          Listen                     424           
[00:12:17] VERBOSE: ::                                  445       ::                                  0          Listen                     4             
[00:12:17] VERBOSE: ::                                  135       ::                                  0          Listen                     620           
[00:12:17] VERBOSE: 0.0.0.0                             1035      0.0.0.0                             0          Bound                      2928          
[00:12:17] VERBOSE: 0.0.0.0                             1032      0.0.0.0                             0          Bound                      2700          
[00:12:17] VERBOSE: 0.0.0.0                             1031      0.0.0.0                             0          Bound                      2700          
[00:12:17] VERBOSE: 0.0.0.0                             1030      0.0.0.0                             0          Bound                      2700          
[00:12:17] VERBOSE: 0.0.0.0                             3389      0.0.0.0                             0          Listen                     1264          
[00:12:17] VERBOSE: 0.0.0.0                             1235      0.0.0.0                             0          Listen                     568           
[00:12:17] VERBOSE: 10.0.0.17                           1035      138.91.141.243                      443        Established Internet       2928          
[00:12:17] VERBOSE: 0.0.0.0                             1029      0.0.0.0                             0          Listen                     524           
[00:12:17] VERBOSE: 0.0.0.0                             1028      0.0.0.0                             0          Listen                     516           
[00:12:17] VERBOSE: 0.0.0.0                             1027      0.0.0.0                             0          Listen                     748           
[00:12:17] VERBOSE: 0.0.0.0                             1026      0.0.0.0                             0          Listen                     720           
[00:12:17] VERBOSE: 0.0.0.0                             1025      0.0.0.0                             0          Listen                     424           
[00:12:17] VERBOSE: 10.0.0.17                           139       0.0.0.0                             0          Listen                     4             
[00:12:17] VERBOSE: 0.0.0.0                             135       0.0.0.0                             0          Listen                     620           
[00:12:17] VERBOSE: 

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug The issue is a bug. in progress The issue is being actively worked on by someone.
Projects
None yet
1 participant