Skip to content

Instantly share code, notes, and snippets.

@Iristyle

Iristyle/Commands.md Secret

Last active November 8, 2017 23:00
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save Iristyle/56b3108be7c9b401effe21a364880b74 to your computer and use it in GitHub Desktop.
Save Iristyle/56b3108be7c9b401effe21a364880b74 to your computer and use it in GitHub Desktop.
Download ZIP
Bolt WinRM Execution Bleed Tests
Raw
Commands.md

Commands

bundle exec bolt plan run sample::bleed_command_test nodes=winrm://vagrant:vagrant@localhost:55985 --modulepath ./spec/fixtures/modules --debug --verbose

spec/fixtures/modules/sample/plans/bleed_command_test.pp

plan sample::bleed_command_test(String $nodes) {

  $node_list = split($nodes, ',')
  $ps_command = '"InstanceId is " + $Host.InstanceId.ToString(); "RunspaceId is " + $Host.Runspace.InstanceId; Write-Host "Foo: $ENV:Foo /  MyValue: $MyValue"; $ENV:Foo = "bar"; $MyValue = "baz"; Write-Host "Foo: $ENV:Foo /  MyValue: $MyValue"'

  run_command($ps_command, $node_list)

  run_command($ps_command, $node_list)
}

Results

2017-11-07T13:23:30.924800  DEBUG executor: Started with 1 thread(s)
2017-11-07T13:23:38.068498  DEBUG localhost: Opened session
2017-11-07T13:23:38.068550  INFO localhost: Running command: "InstanceId is " + $Host.InstanceId.ToString(); "RunspaceId is " + $Host.Runspace.InstanceId; Write-Host "Foo: $ENV:Foo /  MyValue: $MyValue"; $ENV:Foo = "bar"; $MyValue = "baz"; Write-Host "Foo: $ENV:Foo /  MyValue: $MyValue"
2017-11-07T13:23:38.068589  DEBUG localhost: Executing command: "InstanceId is " + $Host.InstanceId.ToString(); "RunspaceId is " + $Host.Runspace.InstanceId; Write-Host "Foo: $ENV:Foo /  MyValue: $MyValue"; $ENV:Foo = "bar"; $MyValue = "baz"; Write-Host "Foo: $ENV:Foo /  MyValue: $MyValue"
2017-11-07T13:23:38.522970  DEBUG localhost: stdout: InstanceId is 8c891691-f7dc-4dda-be63-65baaf8df0c8

2017-11-07T13:23:38.523020  DEBUG localhost: stderr:
2017-11-07T13:23:38.524123  DEBUG localhost: stdout: RunspaceId is 358cebfe-4d35-4be9-8376-7fc82e273f4f

2017-11-07T13:23:38.524153  DEBUG localhost: stderr:
2017-11-07T13:23:38.525786  DEBUG localhost: stdout: Foo:  /  MyValue:

2017-11-07T13:23:38.525810  DEBUG localhost: stderr:
2017-11-07T13:23:38.527259  DEBUG localhost: stdout: Foo: bar /  MyValue: baz

2017-11-07T13:23:38.527279  DEBUG localhost: stderr:
2017-11-07T13:23:38.565868  DEBUG localhost: Command returned successfully
2017-11-07T13:23:38.572638  DEBUG localhost: Closed session
2017-11-07T13:23:38.573462  DEBUG executor: Started with 1 thread(s)
2017-11-07T13:23:45.416885  DEBUG localhost: Opened session
2017-11-07T13:23:45.416925  INFO localhost: Running command: "InstanceId is " + $Host.InstanceId.ToString(); "RunspaceId is " + $Host.Runspace.InstanceId; Write-Host "Foo: $ENV:Foo /  MyValue: $MyValue"; $ENV:Foo = "bar"; $MyValue = "baz"; Write-Host "Foo: $ENV:Foo /  MyValue: $MyValue"
2017-11-07T13:23:45.416965  DEBUG localhost: Executing command: "InstanceId is " + $Host.InstanceId.ToString(); "RunspaceId is " + $Host.Runspace.InstanceId; Write-Host "Foo: $ENV:Foo /  MyValue: $MyValue"; $ENV:Foo = "bar"; $MyValue = "baz"; Write-Host "Foo: $ENV:Foo /  MyValue: $MyValue"
2017-11-07T13:23:45.866088  DEBUG localhost: stdout: InstanceId is 47f88c45-e4d1-4a97-8710-cf35ffc66604

2017-11-07T13:23:45.866216  DEBUG localhost: stderr:
2017-11-07T13:23:45.867258  DEBUG localhost: stdout: RunspaceId is 40c820cc-1911-4327-b8b9-edee4143ee72

2017-11-07T13:23:45.867340  DEBUG localhost: stderr:
2017-11-07T13:23:45.869313  DEBUG localhost: stdout: Foo:  /  MyValue:

2017-11-07T13:23:45.869340  DEBUG localhost: stderr:
2017-11-07T13:23:45.870923  DEBUG localhost: stdout: Foo: bar /  MyValue: baz

2017-11-07T13:23:45.870944  DEBUG localhost: stderr:
2017-11-07T13:23:45.914421  DEBUG localhost: Command returned successfully
2017-11-07T13:23:45.920787  DEBUG localhost: Closed session
ExecutionResult({'winrm://vagrant:vagrant@localhost:55985' => {'stdout' => "InstanceId is 47f88c45-e4d1-4a97-8710-cf35ffc66604\r\nRunspaceId is 40c820cc-1911-4327-b8b9-edee4143ee72\r\nFoo:  /  MyValue: \r\nFoo: bar /  MyValue: baz\r\n", 'stderr' => '', 'exit_code' => 0}})

Summarized, we get the following:

  • 1st invocation - InstanceId is 8c891691-f7dc-4dda-be63-65baaf8df0c8 and Runspace InstanceId is 358cebfe-4d35-4be9-8376-7fc82e273f4f
  • 2nd invocation - InstanceId is 47f88c45-e4d1-4a97-8710-cf35ffc66604 and Runspace InstanceId is 40c820cc-1911-4327-b8b9-edee4143ee72

As such, the env var / variable set in the first invocation does not bleed to the next: Foo: / MyValue:

Raw
Scripts.md

Scripts

NOTE: This is based on the code at the branch https://github.com/puppetlabs/puppet/commits/a28fc17fb and requires changing https://github.com/puppetlabs/puppet/blob/22638660973d96eacfad20d4d525ef100643030d/lib/puppet/functions/run_script.rb#L49 from executor.run_script(executor.from_uris(hosts), found) to executor.run_script(executor.from_uris(hosts), found, []) to match Bolts executor method signature for run_script

A PR is up at puppetlabs/puppet#6339

bundle exec bolt plan run sample::bleed_script_test nodes=winrm://vagrant:vagrant@localhost:55985 --modulepath ./spec/fixtures/modules --debug --verbose

spec/fixtures/modules/sample/plans/bleed_script_test.pp

plan sample::bleed_script_test(String $nodes) {

  $node_list = split($nodes, ',')
  $script_file = "sample/uploads/bleed.ps1"

  run_script($script_file, $node_list)
  run_script($script_file, $node_list)
}

spec/fixtures/modules/sample/files/uploads/bleed.ps1

"InstanceId is " + $Host.InstanceId
"RunspaceId is " + $Host.Runspace.InstanceId
Write-Host "Foo: $ENV:Foo /  MyValue: $MyValue"
$ENV:Foo = "bar"
$MyValue = "baz"
Write-Host "Foo: $ENV:Foo /  MyValue: $MyValue"

Results

2017-11-07T14:04:14.210702  DEBUG executor: Started with 1 thread(s)
2017-11-07T14:04:21.225904  DEBUG localhost: Opened session
2017-11-07T14:04:21.225950  INFO localhost: Running script '/Users/Iristyle/source/bolt/spec/fixtures/modules/sample/files/uploads/bleed.ps1'
2017-11-07T14:04:21.225988  DEBUG localhost: Executing command: $parent = [System.IO.Path]::GetTempPath()
$name = [System.IO.Path]::GetRandomFileName()
$path = Join-Path $parent $name
New-Item -ItemType Directory -Path $path | Out-Null
$path

2017-11-07T14:04:21.576239  DEBUG localhost: stdout: C:\Users\vagrant\AppData\Local\Temp\zwrsvvme.mui

2017-11-07T14:04:21.576294  DEBUG localhost: stderr:
2017-11-07T14:04:21.622373  DEBUG localhost: Command returned successfully
2017-11-07T14:04:21.622482  DEBUG localhost: Uploading /Users/Iristyle/source/bolt/spec/fixtures/modules/sample/files/uploads/bleed.ps1 to C:\Users\vagrant\AppData\Local\Temp\zwrsvvme.mui\bleed.ps1
2017-11-07T14:04:29.529575  DEBUG localhost: Executing command:
$ENV:PATH += ";${ENV:ProgramFiles}\Puppet Labs\Puppet\bin\;" +
  "${ENV:ProgramFiles}\Puppet Labs\Puppet\sys\ruby\bin\"
$ENV:RUBYLIB = "${ENV:ProgramFiles}\Puppet Labs\Puppet\puppet\lib;" +
  "${ENV:ProgramFiles}\Puppet Labs\Puppet\facter\lib;" +
  "${ENV:ProgramFiles}\Puppet Labs\Puppet\hiera\lib;" +
  $ENV:RUBYLIB

function Invoke-Interpreter
{
  [CmdletBinding()]
  Param (
    [Parameter()]
    [String]
    $Path,

    [Parameter()]
    [String]
    $Arguments,

    [Parameter()]
    [Int32]
    $Timeout,

    [Parameter()]
    [String]
    $StdinInput = $Null
  )

  try
  {
    if (-not (Get-Command $Path -ErrorAction SilentlyContinue))
    {
      throw "Could not find executable '$Path' in ${ENV:PATH} on target node"
    }

    $startInfo = New-Object System.Diagnostics.ProcessStartInfo($Path, $Arguments)
    $startInfo.UseShellExecute = $false
    $startInfo.WorkingDirectory = Split-Path -Parent (Get-Command $Path).Path
    $startInfo.CreateNoWindow = $true
    if ($StdinInput) { $startInfo.RedirectStandardInput = $true }
    $startInfo.RedirectStandardOutput = $true
    $startInfo.RedirectStandardError = $true

    $stdoutHandler = { if (-not ([String]::IsNullOrEmpty($EventArgs.Data))) { $Host.UI.WriteLine($EventArgs.Data) } }
    $stderrHandler = { if (-not ([String]::IsNullOrEmpty($EventArgs.Data))) { $Host.UI.WriteErrorLine($EventArgs.Data) } }
    $invocationId = [Guid]::NewGuid().ToString()

    $process = New-Object System.Diagnostics.Process
    $process.StartInfo = $startInfo
    $process.EnableRaisingEvents = $true

    # https://msdn.microsoft.com/en-us/library/system.diagnostics.process.standarderror(v=vs.110).aspx#Anchor_2
    $stdoutEvent = Register-ObjectEvent -InputObject $process -EventName 'OutputDataReceived' -Action $stdoutHandler
    $stderrEvent = Register-ObjectEvent -InputObject $process -EventName 'ErrorDataReceived' -Action $stderrHandler
    $exitedEvent = Register-ObjectEvent -InputObject $process -EventName 'Exited' -SourceIdentifier $invocationId

    $process.Start() | Out-Null

    $process.BeginOutputReadLine()
    $process.BeginErrorReadLine()

    if ($StdinInput)
    {
      $process.StandardInput.WriteLine($StdinInput)
      $process.StandardInput.Close()
    }

    # park current thread until the PS event is signaled upon process exit
    # OR the timeout has elapsed
    $waitResult = Wait-Event -SourceIdentifier $invocationId -Timeout $Timeout
    if (! $process.HasExited)
    {
      $Host.UI.WriteErrorLine("Process $Path did not complete in $Timeout seconds")
      return 1
    }

    return $process.ExitCode
  }
  catch
  {
    $Host.UI.WriteErrorLine($_)
    return 1
  }
  finally
  {
    @($stdoutEvent, $stderrEvent, $exitedEvent) |
      ? { $_ -ne $Null } |
      % { Unregister-Event -SourceIdentifier $_.Name }

    if ($process -ne $Null)
    {
      if (($process.Handle -ne $Null) -and (! $process.HasExited))
      {
        try { $process.Kill() } catch { $Host.UI.WriteErrorLine("Failed To Kill Process $Path") }
      }
      $process.Dispose()
    }
  }
}

2017-11-07T14:04:29.722427  DEBUG localhost: Command returned successfully
2017-11-07T14:04:29.722670  DEBUG localhost: Executing command: $quoted_array = @(
  '-NoProfile','-NonInteractive','-NoLogo','-ExecutionPolicy','Bypass','-File','"C:\Users\vagrant\AppData\Local\Temp\zwrsvvme.mui\bleed.ps1"'
)

$invokeArgs = @{
  Path = "powershell.exe"
  Arguments = $quoted_array -Join ' '
  Timeout = 600

}

# winrm gem checks $? prior to using $LASTEXITCODE
# making it necessary to exit with the desired code to propagate status properly
exit $(Invoke-Interpreter @invokeArgs)

2017-11-07T14:04:33.052682  DEBUG localhost: stdout: InstanceId is 8affd834-09ca-4062-b749-bcc9b77d92c8

2017-11-07T14:04:33.052745  DEBUG localhost: stderr:
2017-11-07T14:04:33.055606  DEBUG localhost: stdout: RunspaceId is 02bb07a2-5685-4e59-a2b0-170e041702ac

2017-11-07T14:04:33.055654  DEBUG localhost: stderr:
2017-11-07T14:04:33.058464  DEBUG localhost: stdout: Foo:  /  MyValue:

2017-11-07T14:04:33.058512  DEBUG localhost: stderr:
2017-11-07T14:04:33.061493  DEBUG localhost: stdout: Foo: bar /  MyValue: baz

2017-11-07T14:04:33.061538  DEBUG localhost: stderr:
2017-11-07T14:04:33.081333  DEBUG localhost: Command returned successfully
2017-11-07T14:04:33.081383  DEBUG localhost: Executing command: Remove-Item -Force "C:\Users\vagrant\AppData\Local\Temp\zwrsvvme.mui\bleed.ps1"
Remove-Item -Force "C:\Users\vagrant\AppData\Local\Temp\zwrsvvme.mui"

2017-11-07T14:04:33.128322  DEBUG localhost: Command returned successfully
2017-11-07T14:04:33.136884  DEBUG localhost: Closed session
2017-11-07T14:04:33.137897  DEBUG executor: Started with 1 thread(s)
2017-11-07T14:04:34.999464  DEBUG localhost: Opened session
2017-11-07T14:04:34.999522  INFO localhost: Running script '/Users/Iristyle/source/bolt/spec/fixtures/modules/sample/files/uploads/bleed.ps1'
2017-11-07T14:04:34.999543  DEBUG localhost: Executing command: $parent = [System.IO.Path]::GetTempPath()
$name = [System.IO.Path]::GetRandomFileName()
$path = Join-Path $parent $name
New-Item -ItemType Directory -Path $path | Out-Null
$path

2017-11-07T14:04:35.078009  DEBUG localhost: stdout: C:\Users\vagrant\AppData\Local\Temp\olrvq42v.te2

2017-11-07T14:04:35.078073  DEBUG localhost: stderr:
2017-11-07T14:04:35.088035  DEBUG localhost: Command returned successfully
2017-11-07T14:04:35.088110  DEBUG localhost: Uploading /Users/Iristyle/source/bolt/spec/fixtures/modules/sample/files/uploads/bleed.ps1 to C:\Users\vagrant\AppData\Local\Temp\olrvq42v.te2\bleed.ps1
2017-11-07T14:04:37.119690  DEBUG localhost: Executing command:
$ENV:PATH += ";${ENV:ProgramFiles}\Puppet Labs\Puppet\bin\;" +
  "${ENV:ProgramFiles}\Puppet Labs\Puppet\sys\ruby\bin\"
$ENV:RUBYLIB = "${ENV:ProgramFiles}\Puppet Labs\Puppet\puppet\lib;" +
  "${ENV:ProgramFiles}\Puppet Labs\Puppet\facter\lib;" +
  "${ENV:ProgramFiles}\Puppet Labs\Puppet\hiera\lib;" +
  $ENV:RUBYLIB

function Invoke-Interpreter
{
  [CmdletBinding()]
  Param (
    [Parameter()]
    [String]
    $Path,

    [Parameter()]
    [String]
    $Arguments,

    [Parameter()]
    [Int32]
    $Timeout,

    [Parameter()]
    [String]
    $StdinInput = $Null
  )

  try
  {
    if (-not (Get-Command $Path -ErrorAction SilentlyContinue))
    {
      throw "Could not find executable '$Path' in ${ENV:PATH} on target node"
    }

    $startInfo = New-Object System.Diagnostics.ProcessStartInfo($Path, $Arguments)
    $startInfo.UseShellExecute = $false
    $startInfo.WorkingDirectory = Split-Path -Parent (Get-Command $Path).Path
    $startInfo.CreateNoWindow = $true
    if ($StdinInput) { $startInfo.RedirectStandardInput = $true }
    $startInfo.RedirectStandardOutput = $true
    $startInfo.RedirectStandardError = $true

    $stdoutHandler = { if (-not ([String]::IsNullOrEmpty($EventArgs.Data))) { $Host.UI.WriteLine($EventArgs.Data) } }
    $stderrHandler = { if (-not ([String]::IsNullOrEmpty($EventArgs.Data))) { $Host.UI.WriteErrorLine($EventArgs.Data) } }
    $invocationId = [Guid]::NewGuid().ToString()

    $process = New-Object System.Diagnostics.Process
    $process.StartInfo = $startInfo
    $process.EnableRaisingEvents = $true

    # https://msdn.microsoft.com/en-us/library/system.diagnostics.process.standarderror(v=vs.110).aspx#Anchor_2
    $stdoutEvent = Register-ObjectEvent -InputObject $process -EventName 'OutputDataReceived' -Action $stdoutHandler
    $stderrEvent = Register-ObjectEvent -InputObject $process -EventName 'ErrorDataReceived' -Action $stderrHandler
    $exitedEvent = Register-ObjectEvent -InputObject $process -EventName 'Exited' -SourceIdentifier $invocationId

    $process.Start() | Out-Null

    $process.BeginOutputReadLine()
    $process.BeginErrorReadLine()

    if ($StdinInput)
    {
      $process.StandardInput.WriteLine($StdinInput)
      $process.StandardInput.Close()
    }

    # park current thread until the PS event is signaled upon process exit
    # OR the timeout has elapsed
    $waitResult = Wait-Event -SourceIdentifier $invocationId -Timeout $Timeout
    if (! $process.HasExited)
    {
      $Host.UI.WriteErrorLine("Process $Path did not complete in $Timeout seconds")
      return 1
    }

    return $process.ExitCode
  }
  catch
  {
    $Host.UI.WriteErrorLine($_)
    return 1
  }
  finally
  {
    @($stdoutEvent, $stderrEvent, $exitedEvent) |
      ? { $_ -ne $Null } |
      % { Unregister-Event -SourceIdentifier $_.Name }

    if ($process -ne $Null)
    {
      if (($process.Handle -ne $Null) -and (! $process.HasExited))
      {
        try { $process.Kill() } catch { $Host.UI.WriteErrorLine("Failed To Kill Process $Path") }
      }
      $process.Dispose()
    }
  }
}

2017-11-07T14:04:37.175677  DEBUG localhost: Command returned successfully
2017-11-07T14:04:37.175772  DEBUG localhost: Executing command: $quoted_array = @(
  '-NoProfile','-NonInteractive','-NoLogo','-ExecutionPolicy','Bypass','-File','"C:\Users\vagrant\AppData\Local\Temp\olrvq42v.te2\bleed.ps1"'
)

$invokeArgs = @{
  Path = "powershell.exe"
  Arguments = $quoted_array -Join ' '
  Timeout = 600

}

# winrm gem checks $? prior to using $LASTEXITCODE
# making it necessary to exit with the desired code to propagate status properly
exit $(Invoke-Interpreter @invokeArgs)

2017-11-07T14:04:40.402221  DEBUG localhost: stdout: InstanceId is 4de92bb2-1bc2-47a9-92be-01cc100b8876

2017-11-07T14:04:40.402264  DEBUG localhost: stderr:
2017-11-07T14:04:40.404069  DEBUG localhost: stdout: RunspaceId is 66d40958-8e60-4ad8-aaea-64b59b0a85be

2017-11-07T14:04:40.404099  DEBUG localhost: stderr:
2017-11-07T14:04:40.405711  DEBUG localhost: stdout: Foo:  /  MyValue:

2017-11-07T14:04:40.405739  DEBUG localhost: stderr:
2017-11-07T14:04:40.407291  DEBUG localhost: stdout: Foo: bar /  MyValue: baz

2017-11-07T14:04:40.407315  DEBUG localhost: stderr:
2017-11-07T14:04:40.421133  DEBUG localhost: Command returned successfully
2017-11-07T14:04:40.421202  DEBUG localhost: Executing command: Remove-Item -Force "C:\Users\vagrant\AppData\Local\Temp\olrvq42v.te2\bleed.ps1"
Remove-Item -Force "C:\Users\vagrant\AppData\Local\Temp\olrvq42v.te2"

2017-11-07T14:04:40.469602  DEBUG localhost: Command returned successfully
2017-11-07T14:04:40.476808  DEBUG localhost: Closed session
ExecutionResult({'winrm://vagrant:vagrant@localhost:55985' => {'stdout' => "InstanceId is 4de92bb2-1bc2-47a9-92be-01cc100b8876\r\nRunspaceId is 66d40958-8e60-4ad8-aaea-64b59b0a85be\r\nFoo:  /  MyValue: \r\nFoo: bar /  MyValue: baz\r\n", 'stderr' => '', 'exit_code' => 0}})

Summarized, we get the following:

  • 1st invocation - InstanceId is 8affd834-09ca-4062-b749-bcc9b77d92c8 and Runspace InstanceId is 02bb07a2-5685-4e59-a2b0-170e041702ac82e273f4f
  • 2nd invocation - InstanceId is 4de92bb2-1bc2-47a9-92be-01cc100b8876 and Runspace InstanceId is 66d40958-8e60-4ad8-aaea-64b59b0a85be

As such, the env var / variable set in the first invocation does not bleed to the next: Foo: / MyValue:

Raw
Tasks.md

Scripts

bundle exec bolt plan run sample::bleed_task_test nodes=winrm://vagrant:vagrant@localhost:55985 --modulepath ./spec/fixtures/modules --debug --verbose

spec/fixtures/modules/sample/plans/bleed_task_test.pp

plan sample::bleed_task_test(String $nodes) {

  $node_list = split($nodes, ',')

  run_task(sample::bleed, $node_list,
    message => "first task",
  )

  run_task(sample::bleed, $node_list,
    message => "second task",
  )
}

spec/fixtures/modules/sample/tasks/bleed.ps1

"InstanceId is " + $Host.InstanceId
"RunspaceId is " + $Host.Runspace.InstanceId
Write-Host "Foo: $ENV:Foo /  MyValue: $MyValue"
$ENV:Foo = 'bar'
$MyValue = 'baz'
echo "$(hostname) got passed the message: $ENV:PT_message"
Write-Host "Foo: $ENV:Foo /  MyValue: $MyValue"

Results

2017-11-07T14:21:24.186764  DEBUG executor: Started with 1 thread(s)
2017-11-07T14:21:31.184006  DEBUG localhost: Opened session
2017-11-07T14:21:31.184055  INFO localhost: Running task '/Users/Iristyle/source/bolt/spec/fixtures/modules/sample/tasks/bleed.ps1'
2017-11-07T14:21:31.184073  DEBUG localhost: arguments: {"message"=>"first task"}
input_method: both
2017-11-07T14:21:31.184167  DEBUG localhost: Executing command: [Environment]::SetEnvironmentVariable('PT_message', 'first task')
2017-11-07T14:21:31.294739  DEBUG localhost: Command returned successfully
2017-11-07T14:21:31.294788  DEBUG localhost: Executing command: $parent = [System.IO.Path]::GetTempPath()
$name = [System.IO.Path]::GetRandomFileName()
$path = Join-Path $parent $name
New-Item -ItemType Directory -Path $path | Out-Null
$path

2017-11-07T14:21:31.591790  DEBUG localhost: stdout: C:\Users\vagrant\AppData\Local\Temp\v3xtcli3.lpi

2017-11-07T14:21:31.591834  DEBUG localhost: stderr:
2017-11-07T14:21:31.634415  DEBUG localhost: Command returned successfully
2017-11-07T14:21:31.634476  DEBUG localhost: Uploading /Users/Iristyle/source/bolt/spec/fixtures/modules/sample/tasks/bleed.ps1 to C:\Users\vagrant\AppData\Local\Temp\v3xtcli3.lpi\bleed.ps1
2017-11-07T14:21:39.339649  DEBUG localhost: Executing command:
$ENV:PATH += ";${ENV:ProgramFiles}\Puppet Labs\Puppet\bin\;" +
  "${ENV:ProgramFiles}\Puppet Labs\Puppet\sys\ruby\bin\"
$ENV:RUBYLIB = "${ENV:ProgramFiles}\Puppet Labs\Puppet\puppet\lib;" +
  "${ENV:ProgramFiles}\Puppet Labs\Puppet\facter\lib;" +
  "${ENV:ProgramFiles}\Puppet Labs\Puppet\hiera\lib;" +
  $ENV:RUBYLIB

function Invoke-Interpreter
{
  [CmdletBinding()]
  Param (
    [Parameter()]
    [String]
    $Path,

    [Parameter()]
    [String]
    $Arguments,

    [Parameter()]
    [Int32]
    $Timeout,

    [Parameter()]
    [String]
    $StdinInput = $Null
  )

  try
  {
    if (-not (Get-Command $Path -ErrorAction SilentlyContinue))
    {
      throw "Could not find executable '$Path' in ${ENV:PATH} on target node"
    }

    $startInfo = New-Object System.Diagnostics.ProcessStartInfo($Path, $Arguments)
    $startInfo.UseShellExecute = $false
    $startInfo.WorkingDirectory = Split-Path -Parent (Get-Command $Path).Path
    $startInfo.CreateNoWindow = $true
    if ($StdinInput) { $startInfo.RedirectStandardInput = $true }
    $startInfo.RedirectStandardOutput = $true
    $startInfo.RedirectStandardError = $true

    $stdoutHandler = { if (-not ([String]::IsNullOrEmpty($EventArgs.Data))) { $Host.UI.WriteLine($EventArgs.Data) } }
    $stderrHandler = { if (-not ([String]::IsNullOrEmpty($EventArgs.Data))) { $Host.UI.WriteErrorLine($EventArgs.Data) } }
    $invocationId = [Guid]::NewGuid().ToString()

    $process = New-Object System.Diagnostics.Process
    $process.StartInfo = $startInfo
    $process.EnableRaisingEvents = $true

    # https://msdn.microsoft.com/en-us/library/system.diagnostics.process.standarderror(v=vs.110).aspx#Anchor_2
    $stdoutEvent = Register-ObjectEvent -InputObject $process -EventName 'OutputDataReceived' -Action $stdoutHandler
    $stderrEvent = Register-ObjectEvent -InputObject $process -EventName 'ErrorDataReceived' -Action $stderrHandler
    $exitedEvent = Register-ObjectEvent -InputObject $process -EventName 'Exited' -SourceIdentifier $invocationId

    $process.Start() | Out-Null

    $process.BeginOutputReadLine()
    $process.BeginErrorReadLine()

    if ($StdinInput)
    {
      $process.StandardInput.WriteLine($StdinInput)
      $process.StandardInput.Close()
    }

    # park current thread until the PS event is signaled upon process exit
    # OR the timeout has elapsed
    $waitResult = Wait-Event -SourceIdentifier $invocationId -Timeout $Timeout
    if (! $process.HasExited)
    {
      $Host.UI.WriteErrorLine("Process $Path did not complete in $Timeout seconds")
      return 1
    }

    return $process.ExitCode
  }
  catch
  {
    $Host.UI.WriteErrorLine($_)
    return 1
  }
  finally
  {
    @($stdoutEvent, $stderrEvent, $exitedEvent) |
      ? { $_ -ne $Null } |
      % { Unregister-Event -SourceIdentifier $_.Name }

    if ($process -ne $Null)
    {
      if (($process.Handle -ne $Null) -and (! $process.HasExited))
      {
        try { $process.Kill() } catch { $Host.UI.WriteErrorLine("Failed To Kill Process $Path") }
      }
      $process.Dispose()
    }
  }
}

2017-11-07T14:21:39.532474  DEBUG localhost: Command returned successfully
2017-11-07T14:21:39.532568  DEBUG localhost: Executing command: $quoted_array = @(
  '-NoProfile','-NonInteractive','-NoLogo','-ExecutionPolicy','Bypass','-File','"C:\Users\vagrant\AppData\Local\Temp\v3xtcli3.lpi\bleed.ps1"'
)

$invokeArgs = @{
  Path = "powershell.exe"
  Arguments = $quoted_array -Join ' '
  Timeout = 600
  StdinInput = @'
{"message":"first task"}
'@
}

# winrm gem checks $? prior to using $LASTEXITCODE
# making it necessary to exit with the desired code to propagate status properly
exit $(Invoke-Interpreter @invokeArgs)

2017-11-07T14:21:44.357833  DEBUG localhost: stdout: InstanceId is 369b0b3b-c764-47f7-909f-ec98e767f6cc

2017-11-07T14:21:44.357874  DEBUG localhost: stderr:
2017-11-07T14:21:44.359299  DEBUG localhost: stdout: RunspaceId is c8f72421-7b97-4db1-909d-fed918903732

2017-11-07T14:21:44.359320  DEBUG localhost: stderr:
2017-11-07T14:21:44.360663  DEBUG localhost: stdout: Foo:  /  MyValue:

2017-11-07T14:21:44.360684  DEBUG localhost: stderr:
2017-11-07T14:21:44.362064  DEBUG localhost: stdout: Nano got passed the message: first task

2017-11-07T14:21:44.362086  DEBUG localhost: stderr:
2017-11-07T14:21:44.363736  DEBUG localhost: stdout: Foo: bar /  MyValue: baz

2017-11-07T14:21:44.363775  DEBUG localhost: stderr:
2017-11-07T14:21:44.375776  DEBUG localhost: Command returned successfully
2017-11-07T14:21:44.375833  DEBUG localhost: Executing command: Remove-Item -Force "C:\Users\vagrant\AppData\Local\Temp\v3xtcli3.lpi\bleed.ps1"
Remove-Item -Force "C:\Users\vagrant\AppData\Local\Temp\v3xtcli3.lpi"

2017-11-07T14:21:44.418458  DEBUG localhost: Command returned successfully
2017-11-07T14:21:44.426086  DEBUG localhost: Closed session
2017-11-07T14:21:44.426801  DEBUG executor: Started with 1 thread(s)
2017-11-07T14:21:46.158513  DEBUG localhost: Opened session
2017-11-07T14:21:46.158552  INFO localhost: Running task '/Users/Iristyle/source/bolt/spec/fixtures/modules/sample/tasks/bleed.ps1'
2017-11-07T14:21:46.158568  DEBUG localhost: arguments: {"message"=>"second task"}
input_method: both
2017-11-07T14:21:46.158606  DEBUG localhost: Executing command: [Environment]::SetEnvironmentVariable('PT_message', 'second task')
2017-11-07T14:21:46.194485  DEBUG localhost: Command returned successfully
2017-11-07T14:21:46.194537  DEBUG localhost: Executing command: $parent = [System.IO.Path]::GetTempPath()
$name = [System.IO.Path]::GetRandomFileName()
$path = Join-Path $parent $name
New-Item -ItemType Directory -Path $path | Out-Null
$path

2017-11-07T14:21:46.272881  DEBUG localhost: stdout: C:\Users\vagrant\AppData\Local\Temp\o2wczvuq.55n

2017-11-07T14:21:46.272920  DEBUG localhost: stderr:
2017-11-07T14:21:46.283994  DEBUG localhost: Command returned successfully
2017-11-07T14:21:46.284109  DEBUG localhost: Uploading /Users/Iristyle/source/bolt/spec/fixtures/modules/sample/tasks/bleed.ps1 to C:\Users\vagrant\AppData\Local\Temp\o2wczvuq.55n\bleed.ps1
2017-11-07T14:21:48.297304  DEBUG localhost: Executing command:
$ENV:PATH += ";${ENV:ProgramFiles}\Puppet Labs\Puppet\bin\;" +
  "${ENV:ProgramFiles}\Puppet Labs\Puppet\sys\ruby\bin\"
$ENV:RUBYLIB = "${ENV:ProgramFiles}\Puppet Labs\Puppet\puppet\lib;" +
  "${ENV:ProgramFiles}\Puppet Labs\Puppet\facter\lib;" +
  "${ENV:ProgramFiles}\Puppet Labs\Puppet\hiera\lib;" +
  $ENV:RUBYLIB

function Invoke-Interpreter
{
  [CmdletBinding()]
  Param (
    [Parameter()]
    [String]
    $Path,

    [Parameter()]
    [String]
    $Arguments,

    [Parameter()]
    [Int32]
    $Timeout,

    [Parameter()]
    [String]
    $StdinInput = $Null
  )

  try
  {
    if (-not (Get-Command $Path -ErrorAction SilentlyContinue))
    {
      throw "Could not find executable '$Path' in ${ENV:PATH} on target node"
    }

    $startInfo = New-Object System.Diagnostics.ProcessStartInfo($Path, $Arguments)
    $startInfo.UseShellExecute = $false
    $startInfo.WorkingDirectory = Split-Path -Parent (Get-Command $Path).Path
    $startInfo.CreateNoWindow = $true
    if ($StdinInput) { $startInfo.RedirectStandardInput = $true }
    $startInfo.RedirectStandardOutput = $true
    $startInfo.RedirectStandardError = $true

    $stdoutHandler = { if (-not ([String]::IsNullOrEmpty($EventArgs.Data))) { $Host.UI.WriteLine($EventArgs.Data) } }
    $stderrHandler = { if (-not ([String]::IsNullOrEmpty($EventArgs.Data))) { $Host.UI.WriteErrorLine($EventArgs.Data) } }
    $invocationId = [Guid]::NewGuid().ToString()

    $process = New-Object System.Diagnostics.Process
    $process.StartInfo = $startInfo
    $process.EnableRaisingEvents = $true

    # https://msdn.microsoft.com/en-us/library/system.diagnostics.process.standarderror(v=vs.110).aspx#Anchor_2
    $stdoutEvent = Register-ObjectEvent -InputObject $process -EventName 'OutputDataReceived' -Action $stdoutHandler
    $stderrEvent = Register-ObjectEvent -InputObject $process -EventName 'ErrorDataReceived' -Action $stderrHandler
    $exitedEvent = Register-ObjectEvent -InputObject $process -EventName 'Exited' -SourceIdentifier $invocationId

    $process.Start() | Out-Null

    $process.BeginOutputReadLine()
    $process.BeginErrorReadLine()

    if ($StdinInput)
    {
      $process.StandardInput.WriteLine($StdinInput)
      $process.StandardInput.Close()
    }

    # park current thread until the PS event is signaled upon process exit
    # OR the timeout has elapsed
    $waitResult = Wait-Event -SourceIdentifier $invocationId -Timeout $Timeout
    if (! $process.HasExited)
    {
      $Host.UI.WriteErrorLine("Process $Path did not complete in $Timeout seconds")
      return 1
    }

    return $process.ExitCode
  }
  catch
  {
    $Host.UI.WriteErrorLine($_)
    return 1
  }
  finally
  {
    @($stdoutEvent, $stderrEvent, $exitedEvent) |
      ? { $_ -ne $Null } |
      % { Unregister-Event -SourceIdentifier $_.Name }

    if ($process -ne $Null)
    {
      if (($process.Handle -ne $Null) -and (! $process.HasExited))
      {
        try { $process.Kill() } catch { $Host.UI.WriteErrorLine("Failed To Kill Process $Path") }
      }
      $process.Dispose()
    }
  }
}

2017-11-07T14:21:48.351416  DEBUG localhost: Command returned successfully
2017-11-07T14:21:48.351501  DEBUG localhost: Executing command: $quoted_array = @(
  '-NoProfile','-NonInteractive','-NoLogo','-ExecutionPolicy','Bypass','-File','"C:\Users\vagrant\AppData\Local\Temp\o2wczvuq.55n\bleed.ps1"'
)

$invokeArgs = @{
  Path = "powershell.exe"
  Arguments = $quoted_array -Join ' '
  Timeout = 600
  StdinInput = @'
{"message":"second task"}
'@
}

# winrm gem checks $? prior to using $LASTEXITCODE
# making it necessary to exit with the desired code to propagate status properly
exit $(Invoke-Interpreter @invokeArgs)

2017-11-07T14:21:51.437080  DEBUG localhost: stdout: InstanceId is b8f32baf-25cc-457d-91de-286902e2d5da

2017-11-07T14:21:51.437128  DEBUG localhost: stderr:
2017-11-07T14:21:51.438786  DEBUG localhost: stdout: RunspaceId is d536d910-67f3-438a-864f-c964dec5ba16

2017-11-07T14:21:51.438810  DEBUG localhost: stderr:
2017-11-07T14:21:51.440463  DEBUG localhost: stdout: Foo:  /  MyValue:

2017-11-07T14:21:51.440511  DEBUG localhost: stderr:
2017-11-07T14:21:51.442999  DEBUG localhost: stdout: Nano got passed the message: second task

2017-11-07T14:21:51.443030  DEBUG localhost: stderr:
2017-11-07T14:21:51.444583  DEBUG localhost: stdout: Foo: bar /  MyValue: baz

2017-11-07T14:21:51.444607  DEBUG localhost: stderr:
2017-11-07T14:21:51.455066  DEBUG localhost: Command returned successfully
2017-11-07T14:21:51.455106  DEBUG localhost: Executing command: Remove-Item -Force "C:\Users\vagrant\AppData\Local\Temp\o2wczvuq.55n\bleed.ps1"
Remove-Item -Force "C:\Users\vagrant\AppData\Local\Temp\o2wczvuq.55n"

2017-11-07T14:21:51.495191  DEBUG localhost: Command returned successfully
2017-11-07T14:21:51.501119  DEBUG localhost: Closed session
ExecutionResult({'winrm://vagrant:vagrant@localhost:55985' => "InstanceId is b8f32baf-25cc-457d-91de-286902e2d5da\r\nRunspaceId is d536d910-67f3-438a-864f-c964dec5ba16\r\nFoo:  /  MyValue: \r\nNano got passed the message: second task\r\nFoo: bar /  MyValue: baz\r\n"})

Summarized, we get the following:

  • 1st invocation - InstanceId is 369b0b3b-c764-47f7-909f-ec98e767f6cc and Runspace InstanceId is c8f72421-7b97-4db1-909d-fed918903732
  • 2nd invocation - InstanceId is b8f32baf-25cc-457d-91de-286902e2d5da and Runspace InstanceId is d536d910-67f3-438a-864f-c964dec5ba16

As such, the env var / variable set in the first invocation does not bleed to the next: Foo: / MyValue:

@Iristyle
Copy link
Author

Iristyle commented Nov 8, 2017

Note to self: Invoke-Interpreter could should not be sent across the wire multiple times... hmm...

@Iristyle
Copy link
Author

Iristyle commented Nov 8, 2017

There are some additional tests demonstrating state behavior in puppetlabs/bolt#153

The shell_init is occurring multiple times against the same endpoint because when task plans are executed, new WinRM instances (nodes) are created each time. Therefore they will always be new connections, rather than existing connections. This behavior will likely change in the future

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment