WebApplicationHandler: Integration test fails intermittent

[johlju]

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

Sometimes the integration tests fail with the error. Most likely a timing issue when running the integration test RemoveHandlerExcludedOptionalParameters.

Win32Exception: An instance of the service is already running
InvalidOperationException: Cannot start service IISADMIN on computer '.'.

Verbose logs showing the problem

2019-12-31T16:09:32.6536065Z     Context When using MSFT_WebApplicationHandler_RemoveHandlerExcludedOptionalParameters
2019-12-31T16:09:32.7706830Z VERBOSE: Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = 
2019-12-31T16:09:32.7707413Z SendConfigurationApply,'className' = MSFT_DSCLocalConfigurationManager,'namespaceName' = 
2019-12-31T16:09:32.7707696Z root/Microsoft/Windows/DesiredStateConfiguration'.
2019-12-31T16:09:32.7761132Z VERBOSE: An LCM method call arrived from computer fv-az363 with user sid S-1-5-21-453668171-3840814176-1879855198-500.
2019-12-31T16:09:32.7779773Z VERBOSE: [fv-az363]: LCM:  [ Start  Set      ]
2019-12-31T16:09:32.8220577Z VERBOSE: [fv-az363]: LCM:  [ Start  Resource ]  [[WebApplicationHandler]WebHandlerTest]
2019-12-31T16:09:32.8225985Z VERBOSE: [fv-az363]: LCM:  [ Start  Test     ]  [[WebApplicationHandler]WebHandlerTest]
2019-12-31T16:09:32.8236457Z VERBOSE: [fv-az363]:                            [[WebApplicationHandler]WebHandlerTest] Handler is Present 
2019-12-31T16:09:32.8237167Z AnotherTest-WebHandler
2019-12-31T16:09:32.8237368Z VERBOSE: [fv-az363]: LCM:  [ End    Test     ]  [[WebApplicationHandler]WebHandlerTest]  in 0.0000 seconds.
2019-12-31T16:09:32.8237692Z VERBOSE: [fv-az363]: LCM:  [ Start  Set      ]  [[WebApplicationHandler]WebHandlerTest]
2019-12-31T16:09:32.8303153Z VERBOSE: [fv-az363]:                            [[WebApplicationHandler]WebHandlerTest] Handler is Present 
2019-12-31T16:09:32.8303807Z AnotherTest-WebHandler
2019-12-31T16:09:32.8308919Z VERBOSE: [fv-az363]:                            [[WebApplicationHandler]WebHandlerTest] Removing handler 
2019-12-31T16:09:32.8309206Z AnotherTest-WebHandler
2019-12-31T16:09:32.8429647Z VERBOSE: [fv-az363]:                            [[WebApplicationHandler]WebHandlerTest] Performing the operation 
2019-12-31T16:09:32.8430675Z "Remove-WebConfigurationProperty" on target "-PSPath MACHINE/WEBROOT/APPHOST -Name Collection -Location Default Web 
2019-12-31T16:09:32.8435743Z Site/TestDir -Filter /system.webServer/handlers -At @{name="AnotherTest-WebHandler"}".
2019-12-31T16:09:33.8617944Z VERBOSE: [fv-az363]: LCM:  [ End    Set      ]  [[WebApplicationHandler]WebHandlerTest]  in 1.0480 seconds.
2019-12-31T16:09:33.8620558Z VERBOSE: [fv-az363]: LCM:  [ End    Resource ]  [[WebApplicationHandler]WebHandlerTest]
2019-12-31T16:09:33.8634887Z VERBOSE: [fv-az363]: LCM:  [ End    Set      ]
2019-12-31T16:09:33.8637989Z VERBOSE: [fv-az363]: LCM:  [ End    Set      ]    in  1.0950 seconds.
2019-12-31T16:09:33.8654743Z VERBOSE: Operation 'Invoke CimMethod' complete.
2019-12-31T16:09:33.8664201Z VERBOSE: Time taken for configuration job to complete is 1.102 seconds
2019-12-31T16:09:33.8769650Z       [+] Should compile and apply the MOF without throwing 1.19s
2019-12-31T16:09:33.9299132Z VERBOSE: An LCM method call arrived from computer fv-az363 with user sid S-1-5-21-453668171-3840814176-1879855198-500.
2019-12-31T16:09:33.9302813Z VERBOSE: [fv-az363]: LCM:  [ Start  Get      ]      
2019-12-31T16:09:33.9344135Z VERBOSE: [fv-az363]:                            [[WebApplicationHandler]WebHandlerTest] Handler is Absent 
2019-12-31T16:09:33.9345575Z AnotherTest-WebHandler
2019-12-31T16:09:33.9356513Z VERBOSE: [fv-az363]: LCM:  [ End    Get      ]  [[WebApplicationHandler]WebHandlerTest]  in 0.0150 seconds.
2019-12-31T16:09:33.9383695Z VERBOSE: [fv-az363]: LCM:  [ End    Get      ]    in  0.0470 seconds.
2019-12-31T16:09:33.9675772Z       [+] Should be able to call Get-DscConfiguration without throwing 86ms
2019-12-31T16:09:33.9706725Z VERBOSE: Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = TestConfiguration,'className' 
2019-12-31T16:09:33.9708076Z = MSFT_DSCLocalConfigurationManager,'namespaceName' = root/Microsoft/Windows/DesiredStateConfiguration'.
2019-12-31T16:09:33.9744899Z VERBOSE: An LCM method call arrived from computer fv-az363 with user sid S-1-5-21-453668171-3840814176-1879855198-500.
2019-12-31T16:09:33.9762479Z VERBOSE: [fv-az363]: LCM:  [ Start  Test     ]
2019-12-31T16:09:34.0152377Z VERBOSE: [fv-az363]: LCM:  [ Start  Resource ]  [[WebApplicationHandler]WebHandlerTest]
2019-12-31T16:09:34.0155434Z VERBOSE: [fv-az363]: LCM:  [ Start  Test     ]  [[WebApplicationHandler]WebHandlerTest]
2019-12-31T16:09:34.0157542Z VERBOSE: [fv-az363]:                            [[WebApplicationHandler]WebHandlerTest] Handler is Absent 
2019-12-31T16:09:34.0158708Z AnotherTest-WebHandler
2019-12-31T16:09:34.0170133Z VERBOSE: [fv-az363]: LCM:  [ End    Test     ]  [[WebApplicationHandler]WebHandlerTest] True in 0.0000 seconds.
2019-12-31T16:09:34.0174008Z VERBOSE: [fv-az363]: LCM:  [ End    Resource ]  [[WebApplicationHandler]WebHandlerTest]
2019-12-31T16:09:34.0174101Z VERBOSE: [fv-az363]: LCM:  [ End    Test     ]     Completed processing test operation. The operation returned True.
2019-12-31T16:09:34.0174188Z VERBOSE: [fv-az363]: LCM:  [ End    Test     ]    in  0.0310 seconds.
2019-12-31T16:09:34.0251225Z VERBOSE: Operation 'Invoke CimMethod' complete.
2019-12-31T16:09:34.0266163Z VERBOSE: Time taken for configuration job to complete is 0.055 seconds
2019-12-31T16:09:34.0327926Z       [+] Should be able to call Test-DscConfiguration and return true 60ms
2019-12-31T16:09:34.0925750Z       [+] Should remove a handler 12ms
2019-12-31T16:09:34.1438062Z VERBOSE: Restoring web configuration - attempt 1
2019-12-31T16:09:39.3884556Z   [-] Error occurred in test script 'D:\a\1\s\tests\Integration\MSFT_WebApplicationHandler.Integration.Tests.ps1' 0ms
2019-12-31T16:09:39.3886456Z     Win32Exception: An instance of the service is already running
2019-12-31T16:09:39.3886755Z     InvalidOperationException: Cannot start service IISADMIN on computer '.'.
2019-12-31T16:09:39.3887142Z     at Restore-WebConfigurationWrapper, D:\a\1\s\tests\TestHelper\CommonTestHelper.psm1: line 91
2019-12-31T16:09:39.3887601Z     at <ScriptBlock>, D:\a\1\s\tests\Integration\MSFT_WebApplicationHandler.Integration.Tests.ps1: line 216
2019-12-31T16:09:39.3888358Z     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Pester\4.9.0\Pester.psm1: line 1097
2019-12-31T16:09:39.3888735Z     at Invoke-Pester<End>, D:\a\1\s\output\RequiredModules\Pester\4.9.0\Pester.psm1: line 1123
2019-12-31T16:09:39.3889000Z     at <ScriptBlock>, D:\a\1\s\output\RequiredModules\Sampler\0.98.1\tasks\Invoke-Pester.pester.build.ps1: line 261
2019-12-31T16:09:39.3889579Z     at *Task, D:\a\1\s\output\RequiredModules\InvokeBuild\5.5.6\Invoke-Build.ps1: line 531
2019-12-31T16:09:39.3890910Z     at *Task, D:\a\1\s\output\RequiredModules\InvokeBuild\5.5.6\Invoke-Build.ps1: line 504
2019-12-31T16:09:39.3891392Z     at *Task, D:\a\1\s\output\RequiredModules\InvokeBuild\5.5.6\Invoke-Build.ps1: line 504
2019-12-31T16:09:39.3893789Z     at <ScriptBlock><End>, D:\a\1\s\output\RequiredModules\InvokeBuild\5.5.6\Invoke-Build.ps1: line 691
2019-12-31T16:09:39.3895442Z     at <ScriptBlock><Begin>, D:\a\1\s\build.ps1: line 349

Suggested solution to the issue

None

The DSC configuration that is used to reproduce the issue (as detailed as possible)

See integration test.

The operating system the target node is running

Windows Server 2019

Version and build of PowerShell the target node is running

5.1

Version of the DSC module that was used

From branch master.