test-kitchen / kitchen-dsc

A DSC Provisioner for Test-Kitchen
Apache License 2.0
27 stars 8 forks source link

WinRM error during verification stage when a converge reboots #22

Closed mprahl closed 8 years ago

mprahl commented 8 years ago

Using the latest kitchen-dsc and test-kitchen, I am getting an error when I run "kitchen test" on a converge that requires a reboot. Once the converge completes, the verification with Pester fails when trying to use the existing WinRM session.

Here is the relevant debug output:

-----> Setting up <companySplunkInstall-win2012r2-vsphere>...
       Finished setting up <companySplunkInstall-win2012r2-vsphere> (0m0.00s).
-----> Verifying <companySplunkInstall-win2012r2-vsphere>...
       Preparing files for transfer
D      Creating local sandbox in C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160621-6904-oabvso
       Preparing to copy supporting powershell modules.
       Preparing to copy files from C:/Users/username/Documents/companyresources/test/integration/companySplunkInstall to the SUT.
D      Copying C:/Users/username/Documents/companyresources/test/integration/companySplunkInstall/companySplunkInstall.Tests.ps1 to C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160621-6904-oabvso/companySplunkInstall.Tests.ps1
D      [WinRM] reusing existing connection negotiate::http://192.168.1.2:5985/wsman<{:user=>"vagrant", :pass=>"vagrant", :elevated_username=>"vagrant", :elevated_password=>"vagrant", :no_ssl_peer_verification=>true, :disable_sspi=>false, :basic_auth_only=>false}>
D      [WinRM] negotiate::http://192.168.1.2:5985/wsman<{:user=>"vagrant", :pass=>"vagrant", :elevated_username=>"vagrant", :elevated_password=>"vagrant", :no_ssl_peer_verification=>true, :disable_sspi=>false, :basic_auth_only=>false}> (set-executionpolicy unrestricted -force;
$global:ProgressPreference = 'SilentlyContinue'
$VerbosePreference = 'Continue'
$env:psmodulepath += ";$(join-path (resolve-path $env:temp).path 'verifier/modules')";
# $env:psmodulepath -split ';' | % {write-output "PSModulePath contains:"} {write-output "`t$_"}
        function directory($path){
if (test-path $path) {(resolve-path $path).providerpath}
else {(resolve-path (mkdir $path)).providerpath}
        }
        $VerifierModulePath = directory $env:temp/verifier/modules
        $VerifierTestsPath = directory $env:temp/verifier/pester

        function test-module($module){
(get-module $module -list) -ne $null
        }
        if (-not (test-module pester)) {
if (test-module PowerShellGet){
  import-module PowerShellGet -force
  import-module PackageManagement -force
  get-packageprovider -name NuGet -force | out-null
  install-module Pester -force
}
else {
  if (-not (test-module PsGet)){
    iex (new-object Net.WebClient).DownloadString('http://bit.ly/GetPsGet')
  }
  try {
    import-module psget -force -erroraction stop
    Install-Module Pester
  }
  catch {
    Write-Output "Installing from Github"
    $zipfile = join-path(resolve-path "$env:temp/verifier") "pester.zip"
    if (-not (test-path $zipfile)){
      $source = 'https://github.com/pester/Pester/archive/3.3.14.zip'
      [byte[]]$bytes = (new-object System.net.WebClient).DownloadData($source)
      [IO.File]::WriteAllBytes($zipfile, $bytes)
      $bytes = $null
      [gc]::collect()
      write-output "Downloaded Pester.zip"
    }
    write-output "Creating Shell.Application COM object"
    $shellcom = new-object -com shell.application
    Write-Output "Creating COM object for zip file."
    $zipcomobject = $shellcom.namespace($zipfile)
    Write-Output "Creating COM object for module destination."
    $destination = $shellcom.namespace($VerifierModulePath)
    Write-Output "Unpacking zip file."
    $destination.CopyHere($zipcomobject.Items(), 0x610)
    rename-item (join-path $VerifierModulePath "Pester-3.3.14") -newname 'Pester' -force
  }
}
        }
        if (-not (test-module Pester)) {
throw "Unable to install Pester.  Please include Pester in your base image or install during your converge."
        }

)
$$$$$$ #< CLIXML
$$$$$$ <Objs Version="1.1.0.1" xmlns="http://schemas.microsoft.com/powershell/2004/04"><S S="verbose">Populating RepositorySourceLocation property for module Pester.</S><S S="verbose">Loading module from path 'C:\Program Files\WindowsPowerShell\Modules\Pester\3.4.0\Pester.psm1'.</S><S S="verbose">Populating RepositorySourceLocation property for module Pester.</S><S S="verbose">Loading module from path 'C:\Program Files\WindowsPowerShell\Modules\Pester\3.4.0\Pester.psm1'.</S></Objs>
       Transferring files to <companySplunkInstall-win2012r2-vsphere>
D      creating hash for file $env:TEMP\verifier
D      creating hash for directory $env:TEMP\verifier
D      Populating files
D      +++ Adding NamedPipes/NamedPipes.psm1
D      +++ Adding PesterUtil/PesterUtil.psm1
D      +++ Adding ScheduledTaskRunner/ScheduledTaskRunner.psm1
D      === All files added.
D      Running check_files.ps1
D      @{
D        "d42c205f5954942e1355b2f476f3227b" = @{
D          "target" = "$env:TEMP\verifier";
D          "src_basename" = "companySplunkInstall.Tests.ps1";
D          "dst" = "$env:TEMP\verifier"
D        };
D        "deec30762f4c7639a4f2dcb36f57d24c" = @{
D          "target" = "$env:TEMP\winrm-upload\tmpzip-deec30762f4c7639a4f2dcb36f57d24c.zip";
D          "src_basename" = "modules";
D          "dst" = "$env:TEMP\verifier\modules"
D        }
D      }
D      Cleaning up local sandbox in C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160621-6904-oabvso
>>>>>> ------Exception-------
>>>>>> Class: Kitchen::ActionFailed
>>>>>> Message: 1 actions failed.
>>>>>>     Failed to complete #verify action: [WinRM::CommandExecutor#open must be called before any run methods are invoked] on companySplunkInstall-win2012r2-vsphere
>>>>>> ----------------------
>>>>>> Please see .kitchen/logs/kitchen.log for more details
>>>>>> Also try running `kitchen diagnose --all` for configuration

D      ------Exception-------
D      Class: Kitchen::ActionFailed
D      Message: 1 actions failed.
>>>>>>     Failed to complete #verify action: [WinRM::CommandExecutor#open must be called before any run methods are invoked] on companySplunkInstall-win2012r2-vsphere
D      ----------------------
D      ------Backtrace-------
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:187:in `report_errors'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:178:in `run_action'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command/test.rb:45:in `block in call'
D      C:/opscode/chefdk/embedded/lib/ruby/2.1.0/benchmark.rb:279:in `measure'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command/test.rb:41:in `call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/cli.rb:56:in `perform'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/cli.rb:231:in `test'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/thor-0.19.1/lib/thor/command.rb:27:in `run'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/thor-0.19.1/lib/thor/invocation.rb:126:in `invoke_command'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/cli.rb:325:in `invoke_task'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/thor-0.19.1/lib/thor.rb:359:in `dispatch'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/thor-0.19.1/lib/thor/base.rb:440:in `start'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/bin/kitchen:13:in `block in <top (required)>'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/errors.rb:174:in `with_friendly_errors'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/bin/kitchen:13:in `<top (required)>'
D      C:/opscode/chefdk/bin/kitchen:20:in `load'
D      C:/opscode/chefdk/bin/kitchen:20:in `<main>'
D      ----End Backtrace-----
D      -Composite Exception--
D      Class: Kitchen::ActionFailed
D      Message: Failed to complete #verify action: [WinRM::CommandExecutor#open must be called before any run methods are invoked] on companySplunkInstall-win2012r2-vsphere
D      ----------------------
D      ------Backtrace-------
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-1.8.1/lib/winrm/command_executor.rb:180:in `ensure_open_shell!'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-1.8.1/lib/winrm/command_executor.rb:92:in `run_cmd'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-fs-0.4.2/lib/winrm-fs/core/file_transporter.rb:448:in `stream_upload'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-fs-0.4.2/lib/winrm-fs/core/file_transporter.rb:249:in `block in create_remote_hash_file'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-fs-0.4.2/lib/winrm-fs/core/file_transporter.rb:249:in `open'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-fs-0.4.2/lib/winrm-fs/core/file_transporter.rb:249:in `create_remote_hash_file'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-fs-0.4.2/lib/winrm-fs/core/file_transporter.rb:201:in `check_files'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-fs-0.4.2/lib/winrm-fs/core/file_transporter.rb:80:in `block in upload'
D      C:/opscode/chefdk/embedded/lib/ruby/2.1.0/benchmark.rb:279:in `measure'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-fs-0.4.2/lib/winrm-fs/core/file_transporter.rb:78:in `upload'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/transport/winrm.rb:132:in `upload'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/verifier/base.rb:77:in `block in call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/transport/winrm.rb:524:in `reuse_connection'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/transport/winrm.rb:72:in `connection'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/verifier/base.rb:73:in `call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:423:in `block in verify_action'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:513:in `call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:513:in `synchronize_or_call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:478:in `block in action'
D      C:/opscode/chefdk/embedded/lib/ruby/2.1.0/benchmark.rb:279:in `measure'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:477:in `action'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:415:in `verify_action'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:348:in `block in transition_to'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:347:in `each'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:347:in `transition_to'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:160:in `verify'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:189:in `block in test'
D      C:/opscode/chefdk/embedded/lib/ruby/2.1.0/benchmark.rb:279:in `measure'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:185:in `test'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:201:in `public_send'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:201:in `run_action_in_thread'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:173:in `block (2 levels) in run_action'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/logging-2.1.0/lib/logging/diagnostic_context.rb:450:in `call'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/logging-2.1.0/lib/logging/diagnostic_context.rb:450:in `block in create_with_logging_context'
D      ----End Backtrace-----
D      ---Nested Exception---
D      Class: Kitchen::ActionFailed
D      Message: Failed to complete #verify action: [WinRM::CommandExecutor#open must be called before any run methods are invoked]
D      ----------------------
D      ------Backtrace-------
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-1.8.1/lib/winrm/command_executor.rb:180:in `ensure_open_shell!'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-1.8.1/lib/winrm/command_executor.rb:92:in `run_cmd'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-fs-0.4.2/lib/winrm-fs/core/file_transporter.rb:448:in `stream_upload'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-fs-0.4.2/lib/winrm-fs/core/file_transporter.rb:249:in `block in create_remote_hash_file'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-fs-0.4.2/lib/winrm-fs/core/file_transporter.rb:249:in `open'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-fs-0.4.2/lib/winrm-fs/core/file_transporter.rb:249:in `create_remote_hash_file'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-fs-0.4.2/lib/winrm-fs/core/file_transporter.rb:201:in `check_files'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-fs-0.4.2/lib/winrm-fs/core/file_transporter.rb:80:in `block in upload'
D      C:/opscode/chefdk/embedded/lib/ruby/2.1.0/benchmark.rb:279:in `measure'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-fs-0.4.2/lib/winrm-fs/core/file_transporter.rb:78:in `upload'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/transport/winrm.rb:132:in `upload'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/verifier/base.rb:77:in `block in call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/transport/winrm.rb:524:in `reuse_connection'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/transport/winrm.rb:72:in `connection'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/verifier/base.rb:73:in `call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:423:in `block in verify_action'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:513:in `call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:513:in `synchronize_or_call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:478:in `block in action'
D      C:/opscode/chefdk/embedded/lib/ruby/2.1.0/benchmark.rb:279:in `measure'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:477:in `action'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:415:in `verify_action'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:348:in `block in transition_to'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:347:in `each'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:347:in `transition_to'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:160:in `verify'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:189:in `block in test'
D      C:/opscode/chefdk/embedded/lib/ruby/2.1.0/benchmark.rb:279:in `measure'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:185:in `test'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:201:in `public_send'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:201:in `run_action_in_thread'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:173:in `block (2 levels) in run_action'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/logging-2.1.0/lib/logging/diagnostic_context.rb:450:in `call'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/logging-2.1.0/lib/logging/diagnostic_context.rb:450:in `block in create_with_logging_context'
D      ----End Backtrace-----
D      [WinRM] closing remote shell 6CED209D-ED19-4114-8316-AA615DE8C822 on http://192.168.1.2:5985/wsman
D      [WinRM] remote shell 6CED209D-ED19-4114-8316-AA615DE8C822 closed
mwrock commented 8 years ago

heh. I JUST released a fix in winrm-fs 0.4.3. Try updating to that gem.

mwrock commented 8 years ago

see #20

mprahl commented 8 years ago

@mwrock, I'm using chefdk, and I'm wondering how I can make test-kitchen use the latest version of winrm-fs that I installed.

Thanks for the help.

mwrock commented 8 years ago

chef gem install winrm-fs should do the trick

mprahl commented 8 years ago

@mwrock, I'm getting the same error, and kitchen-pester is using winrm-fs 0.4.3.

mwrock commented 8 years ago

yes this does look like a separate issue.

smurawski commented 8 years ago

@PrahlM93 after you get through the converge, can you tell if any of the test files get copied? kitchen exec -c 'dir $env:temp/verifier/' should get the relevant info.

smurawski commented 8 years ago

@PrahlM93 Also, a gist of kitchen diagnose would help.

mprahl commented 8 years ago

@smurawski, here are the results from the kitchen exec.

PS C:\Users\username\Documents\companyresources> kitchen exec -c 'dir $env:temp/verifier/' companySplunkInstall-win2012r2-vsphere
-----> Execute command on companySplunkInstall-win2012r2-vsphere.

           Directory: C:\Users\vagrant\AppData\Local\Temp\verifier

       Mode                LastWriteTime         Length Name
       ----                -------------         ------ ----
       d-----        6/21/2016   3:34 PM                modules
       d-----        6/21/2016   3:34 PM                pester
smurawski commented 8 years ago

@PrahlM93 are you using the "restart_winrm" setting?

mprahl commented 8 years ago

@smurawski, I haven't been but I just tried it and I got the same error.

smurawski commented 8 years ago

@PrahlM93 using that would potentially cause that error - which is why I asked.

Can you share the result of a kitchen diagnose? kitchen-pester doesn't really do anything with the transport directly, so I'm not sure what is causing the shell to close unexpectedly.

For the reboot by DSC, are you letting kitchen-dsc do the reboot or are you letting the LCM do it?

And will the run after the reboot exit cleanly?

mprahl commented 8 years ago

@smurawski, I am letting kitchen-dsc do the reboot, which it does quite well. Thank you for adding that feature in!

Here's a snippet of the kitchen diagnose:

    provisioner:
      command_prefix:
      configuration_data:
      configuration_data_variable: ConfigData
      configuration_name: companySplunkInstall
      configuration_script: Test_Kitchen_DSC_Configuration.ps1
      configuration_script_folder: examples
      dsc_local_configuration_manager:
        action_after_reboot: ContinueConfiguration
        allow_module_overwrite: false
        certificate_id: 29010115C9C0C0B2C9272617DBAF161763FF2D7E
        configuration_mode: ApplyOnly
        configuration_mode_frequency_mins: 30
        debug_mode: None
        reboot_if_needed: false
        refresh_frequency_mins: 30
        refresh_mode: PUSH
      dsc_local_configuration_manager_version: wmf5
      ftp_proxy:
      gallery_name: CompanyNuget
      gallery_uri:
      http_proxy:
      https_proxy:
      kitchen_root: C:/Users/username/Documents/companyresources
      max_retries: 1
      modules_from_gallery:
      - name: xPSDesiredStateConfiguration
        requiredversion: 3.9.0.0
      modules_path: modules
      name: dsc
      nuget_force_bootstrap: true
      retry_on_exit_code: []
      root_path: "$env:TEMP\\kitchen"
      sudo:
      sudo_command:
      test_base_path: C:/Users/username/Documents/companyresources/test/integration
      wait_for_retry: 30
    transport:
      connection_retries: 5
      connection_retry_sleep: 1
      elevated: false
      endpoint_template: http://%{hostname}:%{port}/wsman
      kitchen_root: C:/Users/username/Documents/companyresources
      log_level: :info
      max_wait_until_ready: 600
      name: winrm
      password:
      port: 5985
      rdp_port: 3389
      test_base_path: C:/Users/username/Documents/companyresources/test/integration
      username: administrator
      winrm_transport: :negotiate
    verifier:
      chef_omnibus_root: "/opt/chef"
      command_prefix:
      ftp_proxy:
      http_proxy:
      https_proxy:
      kitchen_root: C:/Users/username/Documents/companyresources
      log_level: :info
      name: pester
      restart_winrm: false
      root_path: "$env:TEMP\\verifier"
      run_as_scheduled_task: false
      sudo:
      sudo_command:
      suite_name: companySplunkInstall
      test_base_path: C:/Users/username/Documents/companyresources/test/integration
      test_folder:
      use_local_pester_module: false
smurawski commented 8 years ago

@PrahlM93 Thanks.. I'll try to replicate.

smurawski commented 8 years ago

@PrahlM93 Could you try against a fresh machine with the action_after_reboot StopConfiguration? If it's set to continue, I can't guaranty where things will be when kitchen reconnects..

mprahl commented 8 years ago

@smurawski, that's a good idea to set in general, but that didn't fix the issue. Thanks for the help by the way.

smurawski commented 8 years ago

@PrahlM93 Sure thing. I'll keep digging, but just wanted to make sure since kitchen-dsc defaults to stopconfiguration which is how I would have tested everything

mwrock commented 8 years ago

I'll look too. One thing that would be helpful if you have it handy @PrahlM93 is the full debug log.

The issue here is that the winrm connection was closed and then we use it again later. Now obviously this is likely due to the fact that the machine was rebooted but what I'd expect to happen is for winrm to retry the connection. Maybe it did and that failed but did not completely fail the run.

A complete debug log should document all connection closures and retries.

smurawski commented 8 years ago

@mwrock I bumped into that scenario when testing the reboot feature, so kitchen explicitly closes the connection after the reboot request exit code is parsed by kitchen and before the next converge cycle (which would re-open the session)

mwrock commented 8 years ago

Oh interesting. Of course I did not do a pull on my local test-kitchen repo so did not see that but it actually perfectly explains this.

If you explicitly call close on a winrm connection, it thinks it is totally done and will raise this error after trying to execute or upload on the same connection. The retry only happens if it was not closed but winrm finds the shell to be orphaned. This will change in winrm v2 and it will always retry.

So at least in the case of winrm, the best thing to do is to not close at all but that might not be the best approach for ssh. Another option is to just change winrm to always retry which would not be hard to get into a 1.8.x.

smurawski commented 8 years ago

@mwrock I'm not sure about that. Since if I close after the first converge, the second converge still happens and that requires opening a new connection - which is happening. After that, it transitions to the verifier. And in his logs, there is still some transport activity happening before things go sideways.

mwrock commented 8 years ago

I'll probably need to run through this to get a feel for the flow. The design is is definitely to fail fast if you try to send commands on a closed connection (https://github.com/WinRb/WinRM/blob/master/lib/winrm/command_executor.rb#L92).

smurawski commented 8 years ago

Same here.

mprahl commented 8 years ago

@mwrock, here is the full debug log:

PS C:\Users\username\Documents\companyresources> kitchen test companySplunkInstall-win2012r2-vsphere -l debug
-----> Starting Kitchen (v1.10.0)
D      winrm requested, loading winrm gem (["~> 1.6"])
D      winrm is loaded.
D      winrm-fs requested, loading winrm-fs gem (["~> 0.4.1"])
D      winrm-fs is loaded.
D      winrm requested, loading winrm gem (["~> 1.6"])
D      winrm was already loaded.
D      winrm-fs requested, loading winrm-fs gem (["~> 0.4.1"])
D      winrm-fs was already loaded.
D      winrm requested, loading winrm gem (["~> 1.6"])
D      winrm was already loaded.
D      winrm-fs requested, loading winrm-fs gem (["~> 0.4.1"])
D      winrm-fs was already loaded.
D      winrm requested, loading winrm gem (["~> 1.6"])
D      winrm was already loaded.
D      winrm-fs requested, loading winrm-fs gem (["~> 0.4.1"])
D      winrm-fs was already loaded.
D      winrm requested, loading winrm gem (["~> 1.6"])
D      winrm was already loaded.
D      winrm-fs requested, loading winrm-fs gem (["~> 0.4.1"])
D      winrm-fs was already loaded.
D      winrm requested, loading winrm gem (["~> 1.6"])
D      winrm was already loaded.
D      winrm-fs requested, loading winrm-fs gem (["~> 0.4.1"])
D      winrm-fs was already loaded.
D      winrm requested, loading winrm gem (["~> 1.6"])
D      winrm was already loaded.
D      winrm-fs requested, loading winrm-fs gem (["~> 0.4.1"])
D      winrm-fs was already loaded.
D      winrm requested, loading winrm gem (["~> 1.6"])
D      winrm was already loaded.
D      winrm-fs requested, loading winrm-fs gem (["~> 0.4.1"])
D      winrm-fs was already loaded.
D      winrm requested, loading winrm gem (["~> 1.6"])
D      winrm was already loaded.
D      winrm-fs requested, loading winrm-fs gem (["~> 0.4.1"])
D      winrm-fs was already loaded.
D      winrm requested, loading winrm gem (["~> 1.6"])
D      winrm was already loaded.
D      winrm-fs requested, loading winrm-fs gem (["~> 0.4.1"])
D      winrm-fs was already loaded.
D      winrm requested, loading winrm gem (["~> 1.6"])
D      winrm was already loaded.
D      winrm-fs requested, loading winrm-fs gem (["~> 0.4.1"])
D      winrm-fs was already loaded.
-----> Cleaning up any prior instances of <companySplunkInstall-win2012r2-vsphere>
-----> Destroying <companySplunkInstall-win2012r2-vsphere>...
       Finished destroying <companySplunkInstall-win2012r2-vsphere> (0m0.00s).
-----> Testing <companySplunkInstall-win2012r2-vsphere>
-----> Creating <companySplunkInstall-win2012r2-vsphere>...
[2016-06-22T07:54:48-04:00] WARN: No cookbooks directory found at or above current directory.  Assuming C:/Users/username/Documents/companyresources.
creating machine companySplunkInstall-win2012r2-vsphere-39133b6e on vsphere://vsphere.company.local/sdk?use_ssl=true&insecure=true
  use_linked_clone: true
  datacenter: "Dev Datacenter"
  template_name: "win12r2wmf5"
  template_folder: "DSC"
  vm_folder: "DSC"
  ssh: {:user=>"vagrant", :password=>"vagrant"}
establishing connection to vsphere.company.local
Machine - created - companySplunkInstall-win2012r2-vsphere-39133b6e (5030e58e-ae9d-243a-2290-be09c1759bf4 on vsphere://vsphere.company.local/sdk?use_ssl=true&insecure=true)
Power on VM [DSC/companySplunkInstall-win2012r2-vsphere-39133b6e]
waiting for companySplunkInstall-win2012r2-vsphere-39133b6e (5030e58e-ae9d-243a-2290-be09c1759bf4 on vsphere://vsphere.company.local/sdk?use_ssl=true&insecure=true) to be ready ...
............companySplunkInstall-win2012r2-vsphere-39133b6e is now ready
 WARN  WinRM::WinRMWebService : WinRM::WinRMWebService#run_powershell_script is deprecated. Use WinRM::CommandExecutor#run_powershell_script instead
waiting up to 180 seconds for customization
IP addresses found: ["fe80::1919:3454:5a13:9293", "192.168.1.3"]
 WARN  WinRM::WinRMWebService : WinRM::WinRMWebService#run_powershell_script is deprecated. Use WinRM::CommandExecutor#run_powershell_script instead

Path
----
C:\Users\vagrant

IP address obtained: 192.168.1.3
 WARN  WinRM::WinRMWebService : WinRM::WinRMWebService#run_powershell_script is deprecated. Use WinRM::CommandExecutor#run_powershell_script instead

Path
----
C:\Users\vagrant

create node companySplunkInstall-win2012r2-vsphere-39133b6e at chefzero://localhost:8889
  add normal.chef_provisioning = {"reference"=>{"driver_url"=>"vsphere://vsphere.company.local/sdk?use_ssl=true&insecure=true", "driver_version"=>"0.8.4", "server_id"=>"5030e58e-ae9d-243a-2290-be09c1759bf4", "is_windows"=>true, "allocated_at"=>"2016-06-22 11:54:52 UTC", "ipaddress"=>"192.168.1.3"}}
  add normal.tags = nil
       Finished creating <companySplunkInstall-win2012r2-vsphere> (1m39.49s).
-----> Converging <companySplunkInstall-win2012r2-vsphere>...
       Preparing files for transfer
D      Creating local sandbox in C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-clpyzm
       Staging DSC Resource Modules for copy to the SUT
D      Enumerating C:/Users/username/Documents/companyresources/DSCResources
D      Enumerating C:/Users/username/Documents/companyresources/Examples
D      Enumerating C:/Users/username/Documents/companyresources/companyResources.nuspec
D      Enumerating C:/Users/username/Documents/companyresources/companyResources.psd1
D      Enumerating C:/Users/username/Documents/companyresources/nodes
D      Enumerating C:/Users/username/Documents/companyresources/package.ps1
D      Enumerating C:/Users/username/Documents/companyresources/README.md
D      Enumerating C:/Users/username/Documents/companyresources/test
D      Enumerating C:/Users/username/Documents/companyresources/DSCResources/companySplunk
D      Enumerating C:/Users/username/Documents/companyresources/DSCResources/companySplunk/companySplunk.psd1
D      Enumerating C:/Users/username/Documents/companyresources/DSCResources/companySplunk/companySplunk.schema.psm1
D      Enumerating C:/Users/username/Documents/companyresources/Examples/Sample_companySplunk.ps1
D      Enumerating C:/Users/username/Documents/companyresources/Examples/Test_Kitchen_DSC_Configuration.ps1
D      Enumerating C:/Users/username/Documents/companyresources/nodes/companySplunkInstall-win2012r2-vsphere-39133b6e.json
D      Enumerating C:/Users/username/Documents/companyresources/test/integration
D      Enumerating C:/Users/username/Documents/companyresources/test/integration/companySplunkInstall
D      Enumerating C:/Users/username/Documents/companyresources/test/integration/companySplunkInstall/companySplunkInstall.Tests.ps1
D      Staging C:/Users/username/Documents/companyresources/companyResources.nuspec
D        at C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-clpyzm/modules/companyresources/companyResources.nuspec
D      Staging C:/Users/username/Documents/companyresources/companyResources.psd1
D        at C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-clpyzm/modules/companyresources/companyResources.psd1
D      Staging C:/Users/username/Documents/companyresources/package.ps1
D        at C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-clpyzm/modules/companyresources/package.ps1
D      Staging C:/Users/username/Documents/companyresources/DSCResources/companySplunk/companySplunk.psd1
D        at C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-clpyzm/modules/companyresources/DSCResources/companySplunk/companySplunk.psd1
D      Staging C:/Users/username/Documents/companyresources/DSCResources/companySplunk/companySplunk.schema.psm1
D        at C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-clpyzm/modules/companyresources/DSCResources/companySplunk/companySplunk.schema.psm1
D      Staging C:/Users/username/Documents/companyresources/Examples/Sample_companySplunk.ps1
D        at C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-clpyzm/modules/companyresources/Examples/Sample_companySplunk.ps1
D      Staging C:/Users/username/Documents/companyresources/Examples/Test_Kitchen_DSC_Configuration.ps1
D        at C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-clpyzm/modules/companyresources/Examples/Test_Kitchen_DSC_Configuration.ps1
D      Staging C:/Users/username/Documents/companyresources/nodes/companySplunkInstall-win2012r2-vsphere-39133b6e.json
D        at C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-clpyzm/modules/companyresources/nodes/companySplunkInstall-win2012r2-vsphere-39133b6e.json
D      Staging C:/Users/username/Documents/companyresources/test/integration/companySplunkInstall/companySplunkInstall.Tests.ps1
D        at C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-clpyzm/modules/companyresources/test/integration/companySplunkInstall/companySplunkInstall.Tests.ps1
       Staging DSC configuration script for copy to the SUT
D      Moving C:/Users/username/Documents/companyresources/examples/Test_Kitchen_DSC_Configuration.ps1 to C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-clpyzm/configuration/Test_Kitchen_DSC_Configuration.ps1
D      [WinRM] negotiate::http://192.168.1.3:5985/wsman<{:user=>"vagrant", :pass=>"vagrant", :elevated_username=>"vagrant", :elevated_password=>"vagrant", :no_ssl_peer_verification=>true, :disable_sspi=>false, :basic_auth_only=>false}> ($ProgressPreference = 'SilentlyContinue';
                    [DSCLocalConfigurationManager()]
            configuration SetupLCM
            {
              Settings
              {
                ActionAfterReboot = 'StopConfiguration'
                AllowModuleOverwrite = [bool]::Parse('false')
                CertificateID = '29010115C9C0C0B2C9272617DBAF161763FF2D7E'
                ConfigurationMode = 'ApplyOnly'
                ConfigurationModeFrequencyMins = 15
                DebugMode = 'None'
                RebootNodeIfNeeded = [bool]::Parse('false')
                RefreshFrequencyMins = 30
                RefreshMode = 'PUSH'
              }
            }

        $null = SetupLCM
        Set-DscLocalConfigurationManager -Path ./SetupLCM | out-null
)
D      [WinRM] opening remote shell on http://192.168.1.3:5985/wsman
D      [WinRM] remote shell C517DB4C-7A98-440D-9BD3-E63C62961F20 is open on http://192.168.1.3:5985/wsman
       Bootstrapping the nuget package provider for PowerShell PackageManagement.
D      [WinRM] negotiate::http://192.168.1.3:5985/wsman<{:user=>"vagrant", :pass=>"vagrant", :elevated_username=>"vagrant", :elevated_password=>"vagrant", :no_ssl_peer_verification=>true, :disable_sspi=>false, :basic_auth_only=>false}> ($ProgressPreference = 'SilentlyContinue';
mkdir (split-path (join-path $env:TEMP\kitchen configuration/Test_Kitchen_DSC_Configuration.ps1)) -force | out-null
  install-packageprovider nuget -force -forcebootstrap | out-null

  install-module -name xPSDesiredStateConfiguration -requiredversion 3.9.0.0 -repository companyNuget -force | out-null

)
       Transferring files to <companySplunkInstall-win2012r2-vsphere>
D      creating hash for directory $env:TEMP\kitchen
D      Populating files
D      +++ Adding Test_Kitchen_DSC_Configuration.ps1
D      === All files added.
D      creating hash for directory $env:TEMP\kitchen
D      Populating files
D      +++ Adding companyresources/DSCResources/companySplunk/companySplunk.psd1
D      +++ Adding companyresources/DSCResources/companySplunk/companySplunk.schema.psm1
D      +++ Adding companyresources/Examples/Sample_companySplunk.ps1
D      +++ Adding companyresources/Examples/Test_Kitchen_DSC_Configuration.ps1
D      +++ Adding companyresources/companyResources.nuspec
D      +++ Adding companyresources/companyResources.psd1
D      +++ Adding companyresources/nodes/companySplunkInstall-win2012r2-vsphere-39133b6e.json
D      +++ Adding companyresources/package.ps1
D      +++ Adding companyresources/test/integration/companySplunkInstall/companySplunkInstall.Tests.ps1
D      === All files added.
D      Running check_files.ps1
D      @{
D        "4975f867b12d50351fa1de972564ebe6" = @{
D          "target" = "$env:TEMP\winrm-upload\tmpzip-4975f867b12d50351fa1de972564ebe6.zip";
D          "src_basename" = "configuration";
D          "dst" = "$env:TEMP\kitchen\configuration"
D        };
D        "6e104f52066e1a69e07411f3e5dfb70a" = @{
D          "target" = "$env:TEMP\winrm-upload\tmpzip-6e104f52066e1a69e07411f3e5dfb70a.zip";
D          "src_basename" = "modules";
D          "dst" = "$env:TEMP\kitchen\modules"
D        }
D      }
D      Parsing CSV Response
D      "chk_exists","src_md5","dst_md5","chk_dirty","verifies","target_is_folder"
"False","4975f867b12d50351fa1de972564ebe6",,"True","False","False"
"False","6e104f52066e1a69e07411f3e5dfb70a",,"True","False","False"

D      Uploading C:/Users/username/AppData/Local/Temp/tmpzip-20160622-15820-1p4i45a.zip to encoded tmpfile $env:TEMP\b64-4975f867b12d50351fa1de972564ebe6.txt
D      Finished uploading C:/Users/username/AppData/Local/Temp/tmpzip-20160622-15820-1p4i45a.zip to encoded tmpfile $env:TEMP\b64-4975f867b12d50351fa1de972564ebe6.txt (1.556 KB over 1 chunks) in (0m0.39s)
D      Uploading C:/Users/username/AppData/Local/Temp/tmpzip-20160622-15820-f3ocmj.zip to encoded tmpfile $env:TEMP\b64-6e104f52066e1a69e07411f3e5dfb70a.txt
D      Finished uploading C:/Users/username/AppData/Local/Temp/tmpzip-20160622-15820-f3ocmj.zip to encoded tmpfile $env:TEMP\b64-6e104f52066e1a69e07411f3e5dfb70a.txt (73.216 KB over 10 chunks) in (0m1.90s)
D      Running decode_files.ps1
D      @{
D        "$env:TEMP\b64-4975f867b12d50351fa1de972564ebe6.txt" = @{
D          "dst" = "$env:TEMP\kitchen\configuration";
D          "tmpzip" = "$env:TEMP\winrm-upload\tmpzip-4975f867b12d50351fa1de972564ebe6.zip"
D        };
D        "$env:TEMP\b64-6e104f52066e1a69e07411f3e5dfb70a.txt" = @{
D          "dst" = "$env:TEMP\kitchen\modules";
D          "tmpzip" = "$env:TEMP\winrm-upload\tmpzip-6e104f52066e1a69e07411f3e5dfb70a.zip"
D        }
D      }
D      Parsing CSV Response
D      "src_md5","tmpzip","verifies","tmpfile","dst_md5","dst"
"4975f867b12d50351fa1de972564ebe6","C:\Users\vagrant\AppData\Local\Temp\winrm-upload\tmpzip-4975f867b12d50351fa1de972564ebe6.zip","True","C:\Users\vagrant\AppData\Local\Temp\b64-4975f867b12d50351fa1de972564ebe6.txt","4975f867b12d50351fa1de972564ebe6","C:\Users\vagrant\AppData\Local\Temp\kitchen\configuration"
"6e104f52066e1a69e07411f3e5dfb70a","C:\Users\vagrant\AppData\Local\Temp\winrm-upload\tmpzip-6e104f52066e1a69e07411f3e5dfb70a.zip","True","C:\Users\vagrant\AppData\Local\Temp\b64-6e104f52066e1a69e07411f3e5dfb70a.txt","6e104f52066e1a69e07411f3e5dfb70a","C:\Users\vagrant\AppData\Local\Temp\kitchen\modules"

D      Cleaned up src_zip C:/Users/username/AppData/Local/Temp/tmpzip-20160622-15820-1p4i45a.zip
D      Cleaned up src_zip C:/Users/username/AppData/Local/Temp/tmpzip-20160622-15820-f3ocmj.zip
D      Uploaded 2 items dirty_check: (0m1.83s) stream_files: (0m2.33s) decode: (0m1.80s)
D      Transfer complete
       Moving DSC Resources onto PSModulePath
       Generating the MOF script for the configuration companySplunkInstall
D      Shelling out:           if (Test-Path (join-path $env:TEMP\kitchen 'modules'))
          {
            dir ( join-path $env:TEMP\kitchen 'modules/*') -directory |
              copy-item -destination $env:programfiles/windowspowershell/modules/ -recurse -force
          }
          if (-not (test-path 'c:/configurations'))
          {
            mkdir 'c:/configurations' | out-null
          }
          $ConfigurationScriptPath = Join-path $env:TEMP\kitchen configuration/Test_Kitchen_DSC_Configuration.ps1
          if (-not (test-path $ConfigurationScriptPath))
          {
            throw "Failed to find $ConfigurationScriptPath"
          }
          invoke-expression (get-content $ConfigurationScriptPath -raw)
          if (-not (get-command companySplunkInstall))
          {
            throw "Failed to create a configuration command companySplunkInstall"
          }

          $null = companySplunkInstall -outputpath c:/configurations -configurationdata $ConfigData

D      [WinRM] negotiate::http://192.168.1.3:5985/wsman<{:user=>"vagrant", :pass=>"vagrant", :elevated_username=>"vagrant", :elevated_password=>"vagrant", :no_ssl_peer_verification=>true, :disable_sspi=>false, :basic_auth_only=>false}> ($ProgressPreference = 'SilentlyContinue';
          if (Test-Path (join-path $env:TEMP\kitchen 'modules'))
          {
            dir ( join-path $env:TEMP\kitchen 'modules/*') -directory |
              copy-item -destination $env:programfiles/windowspowershell/modules/ -recurse -force
          }
          if (-not (test-path 'c:/configurations'))
          {
            mkdir 'c:/configurations' | out-null
          }
          $ConfigurationScriptPath = Join-path $env:TEMP\kitchen configuration/Test_Kitchen_DSC_Configuration.ps1
          if (-not (test-path $ConfigurationScriptPath))
          {
            throw "Failed to find $ConfigurationScriptPath"
          }
          invoke-expression (get-content $ConfigurationScriptPath -raw)
          if (-not (get-command companySplunkInstall))
          {
            throw "Failed to create a configuration command companySplunkInstall"
          }

          $null = companySplunkInstall -outputpath c:/configurations -configurationdata $ConfigData
)
$$$$$$ #< CLIXML
$$$$$$ <Objs Version="1.1.0.1" xmlns="http://schemas.microsoft.com/powershell/2004/04"><S S="warning">The configuration 'companySplunkInstall' is loading one or more built-in resources without explicitly importing associated modules. Add Import-DscResource –ModuleName 'PSDesiredStateConfiguration' to your configuration to avoid this message.</S></Objs>
       Running the configuration companySplunkInstall
D      Shelling out:           $job = start-dscconfiguration -Path c:/configurations/ -force
          $job | wait-job
          $verbose_output = $job.childjobs[0].verbose
          $verbose_output
          if ($verbose_output -match 'A reboot is required to progress further. Please reboot the system.') {
            "A reboot is required to continue."
            shutdown /r /t 15
            exit 35
          }
          $dsc_errors = $job.childjobs[0].Error
          if ($dsc_errors -ne $null) {
            $dsc_errors
            exit 1
          }

D      Attempting to execute command - try 1 of 3.
D      [WinRM] negotiate::http://192.168.1.3:5985/wsman<{:user=>"vagrant", :pass=>"vagrant", :elevated_username=>"vagrant", :elevated_password=>"vagrant", :no_ssl_peer_verification=>true, :disable_sspi=>false, :basic_auth_only=>false}> ($ProgressPreference = 'SilentlyContinue';
          $job = start-dscconfiguration -Path c:/configurations/ -force
          $job | wait-job
          $verbose_output = $job.childjobs[0].verbose
          $verbose_output
          if ($verbose_output -match 'A reboot is required to progress further. Please reboot the system.') {
            "A reboot is required to continue."
            shutdown /r /t 15
            exit 35
          }
          $dsc_errors = $job.childjobs[0].Error
          if ($dsc_errors -ne $null) {
            $dsc_errors
            exit 1
          }
)

       Id     Name            PSJobTypeName   State         HasMoreData     Location
       --     ----            -------------   -----         -----------     --------
       1      Job1            Configuratio... Completed     True            localhost
       Perform operation 'Invoke CimMethod' with following parameters, ''methodName'
       = SendConfigurationApply,'className' =
       MSFT_DSCLocalConfigurationManager,'namespaceName' =
       root/Microsoft/Windows/DesiredStateConfiguration'.
       An LCM method call arrived from computer DSCTEST with user sid
       S-1-5-21-2533264337-764142527-4052455684-1001.
       [DSCTEST]: LCM:  [ Start  Set      ]
       [DSCTEST]: LCM:  [ Start  Resource ]
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Test     ]
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ End    Test     ]
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk]  in 0.5790 seconds.
       [DSCTEST]: LCM:  [ Start  Set      ]
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk]
       [DSCTEST]:
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk] Downloading
       http://dscrepository.company.local/SOFTWARE/SPLUNK/Splunk6.3.4.zip to
       C:\Windows\DSCProvisioning\SPLUNK\Splunk6.3.4.zip
       [DSCTEST]:
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk] GET
       http://dscrepository.company.local/SOFTWARE/SPLUNK/Splunk6.3.4.zip with 0-byte
       payload
       [DSCTEST]:
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk] received 53378933-byte
       response of content type application/x-zip-compressed
       [DSCTEST]: LCM:  [ End    Set      ]
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk]  in 2.9210 seconds.
       [DSCTEST]: LCM:  [ End    Resource ]
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Resource ]
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Test     ]
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk]
       [DSCTEST]:
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk] The destination file
       C:\Windows\DSCProvisioning\SPLUNK\Splunk6.3.4\splunkforwarder-6.3.4x64.msi was
       missing or was not a file
       [DSCTEST]: LCM:  [ End    Test     ]
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk]  in 0.2190 seconds.
       [DSCTEST]: LCM:  [ Start  Set      ]
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk]
       [DSCTEST]:
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk] The configuration of
       MSFT_ArchiveResource is starting
       [DSCTEST]:
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk] The archive at
       C:\Windows\DSCProvisioning\SPLUNK\Splunk6.3.4.zip was unpacked to destination
       C:\Windows\DSCProvisioning\SPLUNK\Splunk6.3.4
       [DSCTEST]:
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk] The configuration of
       MSFT_ArchiveResource has completed
       [DSCTEST]: LCM:  [ End    Set      ]
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk]  in 0.4060 seconds.
       [DSCTEST]: LCM:  [ End    Resource ]
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Resource ]
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Test     ]
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk]
       [DSCTEST]:
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk] The system cannot find the
       path specified.
       [DSCTEST]:
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk] The related file/directory
       is: C:\Windows\DepartmentLogs\Agents.
       [DSCTEST]: LCM:  [ End    Test     ]
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk]  in 0.0630 seconds.
       [DSCTEST]: LCM:  [ Start  Set      ]
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk]
       [DSCTEST]:
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk] The system cannot find the
       path specified.
       [DSCTEST]:
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk] The related file/directory
       is: C:\Windows\DepartmentLogs\Agents.
       [DSCTEST]: LCM:  [ End    Set      ]
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk]  in 0.0150 seconds.
       [DSCTEST]: LCM:  [ End    Resource ]
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Resource ]
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Test     ]
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]
       Validate-StandardArguments, Path was
       C:\Windows\DSCProvisioning\SPLUNK\Splunk6.3.4\splunkforwarder-6.3.4x64.msi
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] The path extension
       was .msi
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Parsing
       29032975-1994-4E51-9C9D-A2C545E735B9 as an identifyingNumber
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Parsed
       29032975-1994-4E51-9C9D-A2C545E735B9 as {29032975-1994-4E51-9C9D-A2C545E735B9}
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Ensure is Present
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] product installation
       cannot be determined
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] product as boolean
       is False
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] The package
       UniversalForwarder is not installed
       [DSCTEST]: LCM:  [ End    Test     ]
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]  in 0.1100 seconds.
       [DSCTEST]: LCM:  [ Start  Set      ]
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]
       Validate-StandardArguments, Path was
       C:\Windows\DSCProvisioning\SPLUNK\Splunk6.3.4\splunkforwarder-6.3.4x64.msi
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] The path extension
       was .msi
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Parsing
       29032975-1994-4E51-9C9D-A2C545E735B9 as an identifyingNumber
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Parsed
       29032975-1994-4E51-9C9D-A2C545E735B9 as {29032975-1994-4E51-9C9D-A2C545E735B9}
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Ensure is Present
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] product installation
       cannot be determined
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] product as boolean
       is False
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] The package
       UniversalForwarder is not installed
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]
       Validate-StandardArguments, Path was
       C:\Windows\DSCProvisioning\SPLUNK\Splunk6.3.4\splunkforwarder-6.3.4x64.msi
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] The path extension
       was .msi
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Parsing
       29032975-1994-4E51-9C9D-A2C545E735B9 as an identifyingNumber
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Parsed
       29032975-1994-4E51-9C9D-A2C545E735B9 as {29032975-1994-4E51-9C9D-A2C545E735B9}
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Package
       configuration starting
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Create log file
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Starting
       C:\windows\system32\msiexec.exe with /i
       "C:\Windows\DSCProvisioning\SPLUNK\Splunk6.3.4\splunkforwarder-6.3.4x64.msi"
       /log "C:\Windows\DepartmentLogs\Agents\Splunk6.3.4.log" /quiet AGREETOLICENSE=Yes
       RECEIVING_INDEXER="splunk-win.company.local:9997" ALLUSERS=1 REBOOT=reallysuppress
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Starting process
       C:\windows\system32\msiexec.exe with arguments /i
       "C:\Windows\DSCProvisioning\SPLUNK\Splunk6.3.4\splunkforwarder-6.3.4x64.msi"
       /log "C:\Windows\DepartmentLogs\Agents\Splunk6.3.4.log" /quiet AGREETOLICENSE=Yes
       RECEIVING_INDEXER="splunk-win.company.local:9997" ALLUSERS=1 REBOOT=reallysuppress
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] The machine requires
       a reboot
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Package has been
       installed
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Package
       configuration finished
       [DSCTEST]: LCM:  [ End    Set      ]
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]  in 21.1400 seconds.
       [DSCTEST]: LCM:  [ End    Resource ]
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]
       [DSCTEST]:                            [] A reboot is required to progress
       further. Please reboot the system. Configuration will not be continued after
       the reboot. To continue configuration, use Start-DscConfiguration -UseExisting
       after reboot.
       [DSCTEST]: LCM:  [ End    Set      ]
       [DSCTEST]: LCM:  [ End    Set      ]    in  27.1870 seconds.
       Operation 'Invoke CimMethod' complete.
       A reboot is required to continue.
D      [WinRM] closing remote shell C517DB4C-7A98-440D-9BD3-E63C62961F20 on http://192.168.1.3:5985/wsman
D      [WinRM] remote shell C517DB4C-7A98-440D-9BD3-E63C62961F20 closed
D      Attempting to execute command - try 2 of 3.
D      [WinRM] negotiate::http://192.168.1.3:5985/wsman<{:user=>"vagrant", :pass=>"vagrant", :elevated_username=>"vagrant", :elevated_password=>"vagrant", :no_ssl_peer_verification=>true, :disable_sspi=>false, :basic_auth_only=>false}> ($ProgressPreference = 'SilentlyContinue';
          $job = start-dscconfiguration -Path c:/configurations/ -force
          $job | wait-job
          $verbose_output = $job.childjobs[0].verbose
          $verbose_output
          if ($verbose_output -match 'A reboot is required to progress further. Please reboot the system.') {
            "A reboot is required to continue."
            shutdown /r /t 15
            exit 35
          }
          $dsc_errors = $job.childjobs[0].Error
          if ($dsc_errors -ne $null) {
            $dsc_errors
            exit 1
          }
)
D      [WinRM] opening remote shell on http://192.168.1.3:5985/wsman
D      [WinRM] remote shell 8CF24E4B-973B-4CA6-B10A-F9790CF7BDEA is open on http://192.168.1.3:5985/wsman

       Id     Name            PSJobTypeName   State         HasMoreData     Location
       --     ----            -------------   -----         -----------     --------
       1      Job1            Configuratio... Completed     True            localhost
       Perform operation 'Invoke CimMethod' with following parameters, ''methodName'
       = SendConfigurationApply,'className' =
       MSFT_DSCLocalConfigurationManager,'namespaceName' =
       root/Microsoft/Windows/DesiredStateConfiguration'.
       An LCM method call arrived from computer DSCTEST with user sid
       S-1-5-21-2533264337-764142527-4052455684-1001.
       [DSCTEST]: LCM:  [ Start  Set      ]
       [DSCTEST]: LCM:  [ Start  Resource ]
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Test     ]
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ End    Test     ]
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk]  in 0.2820 seconds.
       [DSCTEST]: LCM:  [ Start  Set      ]
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk]
       [DSCTEST]:
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk] Downloading
       http://dscrepository.company.local/SOFTWARE/SPLUNK/Splunk6.3.4.zip to
       C:\Windows\DSCProvisioning\SPLUNK\Splunk6.3.4.zip
       [DSCTEST]:
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk] GET
       http://dscrepository.company.local/SOFTWARE/SPLUNK/Splunk6.3.4.zip with 0-byte
       payload
       [DSCTEST]:
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk] received 53378933-byte
       response of content type application/x-zip-compressed
       [DSCTEST]: LCM:  [ End    Set      ]
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk]  in 2.7030 seconds.
       [DSCTEST]: LCM:  [ End    Resource ]
       [[xRemoteFile]CopySplunk::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Resource ]
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Test     ]
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ End    Test     ]
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk]  in 0.3120 seconds.
       [DSCTEST]: LCM:  [ Skip   Set      ]
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ End    Resource ]
       [[xArchive]UnzipSplunk::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Resource ]
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Test     ]
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk]
       [DSCTEST]:
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk] The destination object was
       found and no action is required.
       [DSCTEST]: LCM:  [ End    Test     ]
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk]  in 0.0160 seconds.
       [DSCTEST]: LCM:  [ Skip   Set      ]
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ End    Resource ]
       [[File]DepartmentLogsFolder::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Resource ]
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Test     ]
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]
       Validate-StandardArguments, Path was
       C:\Windows\DSCProvisioning\SPLUNK\Splunk6.3.4\splunkforwarder-6.3.4x64.msi
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] The path extension
       was .msi
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Parsing
       29032975-1994-4E51-9C9D-A2C545E735B9 as an identifyingNumber
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Parsed
       29032975-1994-4E51-9C9D-A2C545E735B9 as {29032975-1994-4E51-9C9D-A2C545E735B9}
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] Ensure is Present
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] product HKEY_LOCAL_MA
       CHINE\SOFTWARE\Microsoft\Windows\CurrentVersion\Uninstall\{29032975-1994-4E51-9
       C9D-A2C545E735B9} found
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] product as boolean
       is True
       [DSCTEST]:
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk] The package
       UniversalForwarder is installed
       [DSCTEST]: LCM:  [ End    Test     ]
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]  in 0.0940 seconds.
       [DSCTEST]: LCM:  [ Skip   Set      ]
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ End    Resource ]
       [[Package]SplunkInstallation::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Resource ]
       [[Script]InputConf::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Test     ]
       [[Script]InputConf::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ End    Test     ]
       [[Script]InputConf::[companySplunk]InstallSplunk]  in 0.1250 seconds.
       [DSCTEST]: LCM:  [ Start  Set      ]
       [[Script]InputConf::[companySplunk]InstallSplunk]
       [DSCTEST]:
       [[Script]InputConf::[companySplunk]InstallSplunk] Performing the operation
       "Set-TargetResource" on target "Executing the SetScript with the user supplied
       credential".
       [DSCTEST]: LCM:  [ End    Set      ]
       [[Script]InputConf::[companySplunk]InstallSplunk]  in 6.7810 seconds.
       [DSCTEST]: LCM:  [ End    Resource ]
       [[Script]InputConf::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Resource ]
       [[Script]OutputConf::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ Start  Test     ]
       [[Script]OutputConf::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ End    Test     ]
       [[Script]OutputConf::[companySplunk]InstallSplunk]  in 0.0160 seconds.
       [DSCTEST]: LCM:  [ Start  Set      ]
       [[Script]OutputConf::[companySplunk]InstallSplunk]
       [DSCTEST]:
       [[Script]OutputConf::[companySplunk]InstallSplunk] Performing the operation
       "Set-TargetResource" on target "Executing the SetScript with the user supplied
       credential".
       [DSCTEST]: LCM:  [ End    Set      ]
       [[Script]OutputConf::[companySplunk]InstallSplunk]  in 6.8750 seconds.
       [DSCTEST]: LCM:  [ End    Resource ]
       [[Script]OutputConf::[companySplunk]InstallSplunk]
       [DSCTEST]: LCM:  [ End    Set      ]
       [DSCTEST]: LCM:  [ End    Set      ]    in  18.4530 seconds.
       Operation 'Invoke CimMethod' complete.

D      Cleaning up local sandbox in C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-clpyzm
       Finished converging <companySplunkInstall-win2012r2-vsphere> (2m57.68s).
-----> Setting up <companySplunkInstall-win2012r2-vsphere>...
       Finished setting up <companySplunkInstall-win2012r2-vsphere> (0m0.00s).
-----> Verifying <companySplunkInstall-win2012r2-vsphere>...
       Preparing files for transfer
D      Creating local sandbox in C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-1ozo3js
       Preparing to copy supporting powershell modules.
       Preparing to copy files from C:/Users/username/Documents/companyresources/test/integration/companySplunkInstall to the SUT.
D      Copying C:/Users/username/Documents/companyresources/test/integration/companySplunkInstall/companySplunkInstall.Tests.ps1 to C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-1ozo3js/companySplunkInstall.Tests.ps1
D      [WinRM] reusing existing connection negotiate::http://192.168.1.3:5985/wsman<{:user=>"vagrant", :pass=>"vagrant", :elevated_username=>"vagrant", :elevated_password=>"vagrant", :no_ssl_peer_verification=>true, :disable_sspi=>false, :basic_auth_only=>false}>
D      [WinRM] negotiate::http://192.168.1.3:5985/wsman<{:user=>"vagrant", :pass=>"vagrant", :elevated_username=>"vagrant", :elevated_password=>"vagrant", :no_ssl_peer_verification=>true, :disable_sspi=>false, :basic_auth_only=>false}> (set-executionpolicy unrestricted -force;
$global:ProgressPreference = 'SilentlyContinue'
$VerbosePreference = 'Continue'
$env:psmodulepath += ";$(join-path (resolve-path $env:temp).path 'verifier/modules')";
# $env:psmodulepath -split ';' | % {write-output "PSModulePath contains:"} {write-output "`t$_"}
        function directory($path){
if (test-path $path) {(resolve-path $path).providerpath}
else {(resolve-path (mkdir $path)).providerpath}
        }
        $VerifierModulePath = directory $env:temp/verifier/modules
        $VerifierTestsPath = directory $env:temp/verifier/pester

        function test-module($module){
(get-module $module -list) -ne $null
        }
        if (-not (test-module pester)) {
if (test-module PowerShellGet){
  import-module PowerShellGet -force
  import-module PackageManagement -force
  get-packageprovider -name NuGet -force | out-null
  install-module Pester -force
}
else {
  if (-not (test-module PsGet)){
    iex (new-object Net.WebClient).DownloadString('http://bit.ly/GetPsGet')
  }
  try {
    import-module psget -force -erroraction stop
    Install-Module Pester
  }
  catch {
    Write-Output "Installing from Github"
    $zipfile = join-path(resolve-path "$env:temp/verifier") "pester.zip"
    if (-not (test-path $zipfile)){
      $source = 'https://github.com/pester/Pester/archive/3.3.14.zip'
      [byte[]]$bytes = (new-object System.net.WebClient).DownloadData($source)
      [IO.File]::WriteAllBytes($zipfile, $bytes)
      $bytes = $null
      [gc]::collect()
      write-output "Downloaded Pester.zip"
    }
    write-output "Creating Shell.Application COM object"
    $shellcom = new-object -com shell.application
    Write-Output "Creating COM object for zip file."
    $zipcomobject = $shellcom.namespace($zipfile)
    Write-Output "Creating COM object for module destination."
    $destination = $shellcom.namespace($VerifierModulePath)
    Write-Output "Unpacking zip file."
    $destination.CopyHere($zipcomobject.Items(), 0x610)
    rename-item (join-path $VerifierModulePath "Pester-3.3.14") -newname 'Pester' -force
  }
}
        }
        if (-not (test-module Pester)) {
throw "Unable to install Pester.  Please include Pester in your base image or install during your converge."
        }

)
$$$$$$ #< CLIXML
$$$$$$ <Objs Version="1.1.0.1" xmlns="http://schemas.microsoft.com/powershell/2004/04"><S S="verbose">Populating RepositorySourceLocation property for module Pester.</S><S S="verbose">Loading module from path 'C:\Program Files\WindowsPowerShell\Modules\Pester\3.4.0\Pester.psm1'.</S><S S="verbose">Populating RepositorySourceLocation property for module Pester.</S><S S="verbose">Loading module from path 'C:\Program Files\WindowsPowerShell\Modules\Pester\3.4.0\Pester.psm1'.</S></Objs>
       Transferring files to <companySplunkInstall-win2012r2-vsphere>
D      creating hash for file $env:TEMP\verifier
D      creating hash for directory $env:TEMP\verifier
D      Populating files
D      +++ Adding NamedPipes/NamedPipes.psm1
D      +++ Adding PesterUtil/PesterUtil.psm1
D      +++ Adding ScheduledTaskRunner/ScheduledTaskRunner.psm1
D      === All files added.
D      Running check_files.ps1
D      @{
D        "d42c205f5954942e1355b2f476f3227b" = @{
D          "target" = "$env:TEMP\verifier";
D          "src_basename" = "companySplunkInstall.Tests.ps1";
D          "dst" = "$env:TEMP\verifier"
D        };
D        "deec30762f4c7639a4f2dcb36f57d24c" = @{
D          "target" = "$env:TEMP\winrm-upload\tmpzip-deec30762f4c7639a4f2dcb36f57d24c.zip";
D          "src_basename" = "modules";
D          "dst" = "$env:TEMP\verifier\modules"
D        }
D      }
D      Cleaning up local sandbox in C:/Users/username/AppData/Local/Temp/companySplunkInstall-win2012r2-vsphere-sandbox-20160622-15820-1ozo3js
>>>>>> ------Exception-------
>>>>>> Class: Kitchen::ActionFailed
>>>>>> Message: 1 actions failed.
>>>>>>     Failed to complete #verify action: [WinRM::CommandExecutor#open must be called before any run methods are invoked] on companySplunkInstall-win2012r2-vsphere
>>>>>> ----------------------
>>>>>> Please see .kitchen/logs/kitchen.log for more details
>>>>>> Also try running `kitchen diagnose --all` for configuration

D      ------Exception-------
D      Class: Kitchen::ActionFailed
D      Message: 1 actions failed.
>>>>>>     Failed to complete #verify action: [WinRM::CommandExecutor#open must be called before any run methods are invoked] on companySplunkInstall-win2012r2-vsphere
D      ----------------------
D      ------Backtrace-------
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:187:in `report_errors'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:178:in `run_action'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command/test.rb:45:in `block in call'
D      C:/opscode/chefdk/embedded/lib/ruby/2.1.0/benchmark.rb:279:in `measure'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command/test.rb:41:in `call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/cli.rb:56:in `perform'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/cli.rb:231:in `test'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/thor-0.19.1/lib/thor/command.rb:27:in `run'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/thor-0.19.1/lib/thor/invocation.rb:126:in `invoke_command'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/cli.rb:325:in `invoke_task'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/thor-0.19.1/lib/thor.rb:359:in `dispatch'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/thor-0.19.1/lib/thor/base.rb:440:in `start'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/bin/kitchen:13:in `block in <top (required)>'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/errors.rb:174:in `with_friendly_errors'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/bin/kitchen:13:in `<top (required)>'
D      C:/opscode/chefdk/bin/kitchen:20:in `load'
D      C:/opscode/chefdk/bin/kitchen:20:in `<main>'
D      ----End Backtrace-----
D      -Composite Exception--
D      Class: Kitchen::ActionFailed
D      Message: Failed to complete #verify action: [WinRM::CommandExecutor#open must be called before any run methods are invoked] on companySplunkInstall-win2012r2-vsphere
D      ----------------------
D      ------Backtrace-------
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-1.8.1/lib/winrm/command_executor.rb:180:in `ensure_open_shell!'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-1.8.1/lib/winrm/command_executor.rb:92:in `run_cmd'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/winrm-fs-0.4.3/lib/winrm-fs/core/file_transporter.rb:448:in `stream_upload'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/winrm-fs-0.4.3/lib/winrm-fs/core/file_transporter.rb:249:in `block in create_remote_hash_file'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/winrm-fs-0.4.3/lib/winrm-fs/core/file_transporter.rb:249:in `open'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/winrm-fs-0.4.3/lib/winrm-fs/core/file_transporter.rb:249:in `create_remote_hash_file'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/winrm-fs-0.4.3/lib/winrm-fs/core/file_transporter.rb:201:in `check_files'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/winrm-fs-0.4.3/lib/winrm-fs/core/file_transporter.rb:80:in `block in upload'
D      C:/opscode/chefdk/embedded/lib/ruby/2.1.0/benchmark.rb:279:in `measure'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/winrm-fs-0.4.3/lib/winrm-fs/core/file_transporter.rb:78:in `upload'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/transport/winrm.rb:132:in `upload'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/verifier/base.rb:77:in `block in call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/transport/winrm.rb:524:in `reuse_connection'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/transport/winrm.rb:72:in `connection'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/verifier/base.rb:73:in `call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:423:in `block in verify_action'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:513:in `call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:513:in `synchronize_or_call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:478:in `block in action'
D      C:/opscode/chefdk/embedded/lib/ruby/2.1.0/benchmark.rb:279:in `measure'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:477:in `action'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:415:in `verify_action'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:348:in `block in transition_to'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:347:in `each'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:347:in `transition_to'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:160:in `verify'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:189:in `block in test'
D      C:/opscode/chefdk/embedded/lib/ruby/2.1.0/benchmark.rb:279:in `measure'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:185:in `test'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:201:in `public_send'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:201:in `run_action_in_thread'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:173:in `block (2 levels) in run_action'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/logging-2.1.0/lib/logging/diagnostic_context.rb:450:in `call'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/logging-2.1.0/lib/logging/diagnostic_context.rb:450:in `block in create_with_logging_context'
D      ----End Backtrace-----
D      ---Nested Exception---
D      Class: Kitchen::ActionFailed
D      Message: Failed to complete #verify action: [WinRM::CommandExecutor#open must be called before any run methods are invoked]
D      ----------------------
D      ------Backtrace-------
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-1.8.1/lib/winrm/command_executor.rb:180:in `ensure_open_shell!'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/winrm-1.8.1/lib/winrm/command_executor.rb:92:in `run_cmd'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/winrm-fs-0.4.3/lib/winrm-fs/core/file_transporter.rb:448:in `stream_upload'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/winrm-fs-0.4.3/lib/winrm-fs/core/file_transporter.rb:249:in `block in create_remote_hash_file'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/winrm-fs-0.4.3/lib/winrm-fs/core/file_transporter.rb:249:in `open'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/winrm-fs-0.4.3/lib/winrm-fs/core/file_transporter.rb:249:in `create_remote_hash_file'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/winrm-fs-0.4.3/lib/winrm-fs/core/file_transporter.rb:201:in `check_files'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/winrm-fs-0.4.3/lib/winrm-fs/core/file_transporter.rb:80:in `block in upload'
D      C:/opscode/chefdk/embedded/lib/ruby/2.1.0/benchmark.rb:279:in `measure'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/winrm-fs-0.4.3/lib/winrm-fs/core/file_transporter.rb:78:in `upload'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/transport/winrm.rb:132:in `upload'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/verifier/base.rb:77:in `block in call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/transport/winrm.rb:524:in `reuse_connection'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/transport/winrm.rb:72:in `connection'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/verifier/base.rb:73:in `call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:423:in `block in verify_action'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:513:in `call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:513:in `synchronize_or_call'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:478:in `block in action'
D      C:/opscode/chefdk/embedded/lib/ruby/2.1.0/benchmark.rb:279:in `measure'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:477:in `action'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:415:in `verify_action'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:348:in `block in transition_to'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:347:in `each'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:347:in `transition_to'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:160:in `verify'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:189:in `block in test'
D      C:/opscode/chefdk/embedded/lib/ruby/2.1.0/benchmark.rb:279:in `measure'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/instance.rb:185:in `test'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:201:in `public_send'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:201:in `run_action_in_thread'
D      C:/Users/username/AppData/Local/chefdk/gem/ruby/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/command.rb:173:in `block (2 levels) in run_action'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/logging-2.1.0/lib/logging/diagnostic_context.rb:450:in `call'
D      C:/opscode/chefdk/embedded/lib/ruby/gems/2.1.0/gems/logging-2.1.0/lib/logging/diagnostic_context.rb:450:in `block in create_with_logging_context'
D      ----End Backtrace-----
D      [WinRM] closing remote shell 8CF24E4B-973B-4CA6-B10A-F9790CF7BDEA on http://192.168.1.3:5985/wsman
D      [WinRM] remote shell 8CF24E4B-973B-4CA6-B10A-F9790CF7BDEA closed
smurawski commented 8 years ago

I was able to duplicate the error and will keep digging.

smurawski commented 8 years ago

@PrahlM93 Found the problem ^^ should get an updated release out today or tomorrow.

mprahl commented 8 years ago

@smurawski, I just made the change manually and that fixed it. Great work and I appreciate the help!