[BOLT-1209] Intermittent AppVeyor test failure - WSMAN ERROR CODE: 1018 / WSMAN ERROR CODE: 2147746132 Created: 2019/03/26  Updated: 2019/04/11  Resolved: 2019/04/09

Status: Resolved
Project: Puppet Task Runner
Component/s: Windows
Affects Version/s: None
Fix Version/s: BOLT 1.16.0

Type: Improvement Priority: Normal
Reporter: Ethan Brown Assignee: Ethan Brown
Resolution: Fixed Votes: 0
Labels: docs_reviewed
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Template:
Team: Bolt
Sprint: Bolt Kanban
Release Notes: Not Needed
QA Risk Assessment: Needs Assessment

 Description   

The following code can be used to help decipher the error codes https://p0w3rsh3ll.wordpress.com/2013/03/07/deciphering-winrm-error-codes/.

Error code 1018 is defined in https://docs.microsoft.com/en-us/windows/desktop/Debug/system-error-codes--1000-1299- as

ERROR_KEY_DELETED
1018 (0x3FA)
Illegal operation attempted on a registry key that has been marked for deletion.

2147746132 could be the COM error for REGDB_E_CLASSNOTREG

C:\Users\Iristyle> (New-Object -ComObject WSMAN.Automation).GetErrorMessage((Get-ErrorCode 2147746132).Int64)
Class not registered

Both of these seem to indicate some registry setup may not be complete.

bundle exec rake integration:appveyor_agents fails intermittently with a few different types of winrm errors

Failures:
  1) apply over winrm on Appveyor with Puppet Agents when running against puppet 5 runs a ruby task
     Failure/Error: expect(result[0]).to include('status' => 'success')
       expected {"node" => "winrm://roddypiper@localhost:5985", "result" => {"_error" => {"details" => {}, "issue_code" => "CON... host server and proxy are properly registered. </f:Message></f:WSManFault>"}}, "status" => "failure"} to include {"status" => "success"}
       Diff:
       @@ -1,2 +1,4 @@
       -"status" => "success",
       +"node" => "winrm://roddypiper@localhost:5985",
       +"result" => {"_error"=>{"details"=>{}, "issue_code"=>"CONNECT_ERROR", "kind"=>"puppetlabs.tasks/connect-error", "msg"=>"Failed to connect to http://localhost:5985/wsman: [WSMAN ERROR CODE: 1018]: <f:WSManFault Code='1018' Machine='localhost' xmlns:f='http://schemas.microsoft.com/wbem/wsman/1/wsmanfault'><f:Message>The WSMan service could not launch a host process to process the given request.  Make sure the WSMan provider host server and proxy are properly registered. </f:Message></f:WSManFault>"}},
       +"status" => "failure",
     # ./spec/integration/apply_spec.rb:277:in `block (4 levels) in <top (required)>'
  2) apply over winrm on Appveyor with Puppet Agents when running against puppet 5 runs an apply plan
     Failure/Error: expect(result[0]).to include('status' => 'success')
       expected {"node" => "winrm://roddypiper@localhost:5985", "result" => {"_error" => {"details" => {}, "issue_code" => "CON... host server and proxy are properly registered. </f:Message></f:WSManFault>"}}, "status" => "failure"} to include {"status" => "success"}
       Diff:
       @@ -1,2 +1,4 @@
       -"status" => "success",
       +"node" => "winrm://roddypiper@localhost:5985",
       +"result" => {"_error"=>{"details"=>{}, "issue_code"=>"CONNECT_ERROR", "kind"=>"puppetlabs.tasks/connect-error", "msg"=>"Failed to connect to http://localhost:5985/wsman: [WSMAN ERROR CODE: 1018]: <f:WSManFault Code='1018' Machine='localhost' xmlns:f='http://schemas.microsoft.com/wbem/wsman/1/wsmanfault'><f:Message>The WSMan service could not launch a host process to process the given request.  Make sure the WSMan provider host server and proxy are properly registered. </f:Message></f:WSManFault>"}},
       +"status" => "failure",
     # ./spec/integration/apply_spec.rb:277:in `block (4 levels) in <top (required)>'
  3) apply over winrm on Appveyor with Puppet Agents when running against puppet 5 does not create Boltdir
     Failure/Error: expect(result[0]).to include('status' => 'success')
       expected {"node" => "winrm://roddypiper@localhost:5985", "result" => {"_error" => {"details" => {}, "issue_code" => "CON... host server and proxy are properly registered. </f:Message></f:WSManFault>"}}, "status" => "failure"} to include {"status" => "success"}
       Diff:
       @@ -1,2 +1,4 @@
       -"status" => "success",
       +"node" => "winrm://roddypiper@localhost:5985",
       +"result" => {"_error"=>{"details"=>{}, "issue_code"=>"CONNECT_ERROR", "kind"=>"puppetlabs.tasks/connect-error", "msg"=>"Failed to connect to http://localhost:5985/wsman: [WSMAN ERROR CODE: 1018]: <f:WSManFault Code='1018' Machine='localhost' xmlns:f='http://schemas.microsoft.com/wbem/wsman/1/wsmanfault'><f:Message>The WSMan service could not launch a host process to process the given request.  Make sure the WSMan provider host server and proxy are properly registered. </f:Message></f:WSManFault>"}},
       +"status" => "failure",
     # ./spec/integration/apply_spec.rb:277:in `block (4 levels) in <top (required)>'
Finished in 4 minutes 43.4 seconds (files took 6.31 seconds to load)
6 examples, 3 failures
Failed examples:

https://ci.appveyor.com/project/puppetlabs/bolt/builds/22644221/job/cjaqgb24yowd4mvu

There are another set of of similar errors that show as WSMAN ERROR CODE: 2147746132 as seen in https://ci.appveyor.com/project/puppetlabs/bolt/builds/23350727/job/il4gp64cnrx6qcs2:

Failures:
  1) apply over winrm on Appveyor with Puppet Agents when running against puppet 5 runs a ruby task
     Failure/Error: expect(result[0]).to include('status' => 'success')
       expected {"node" => "winrm://roddypiper@localhost:5985", "result" => {"_error" => {"details" => {}, "issue_code" => "CON... host server and proxy are properly registered. </f:Message></f:WSManFault>"}}, "status" => "failure"} to include {"status" => "success"}
       Diff:
       @@ -1,2 +1,4 @@
       -"status" => "success",
       +"node" => "winrm://roddypiper@localhost:5985",
       +"result" => {"_error"=>{"details"=>{}, "issue_code"=>"CONNECT_ERROR", "kind"=>"puppetlabs.tasks/connect-error", "msg"=>"Failed to connect to http://localhost:5985/wsman: [WSMAN ERROR CODE: 2147746132]: <f:WSManFault Code='2147746132' Machine='localhost' xmlns:f='http://schemas.microsoft.com/wbem/wsman/1/wsmanfault'><f:Message>The WSMan service could not launch a host process to process the given request.  Make sure the WSMan provider host server and proxy are properly registered. </f:Message></f:WSManFault>"}},
       +"status" => "failure",
     # ./spec/integration/apply_spec.rb:274:in `block (4 levels) in <top (required)>'
  2) apply over winrm on Appveyor with Puppet Agents when running against puppet 5 runs an apply plan
     Failure/Error: expect(result[0]).to include('status' => 'success')
       expected {"node" => "winrm://roddypiper@localhost:5985", "result" => {"_error" => {"details" => {}, "issue_code" => "CON... host server and proxy are properly registered. </f:Message></f:WSManFault>"}}, "status" => "failure"} to include {"status" => "success"}
       Diff:
       @@ -1,2 +1,4 @@
       -"status" => "success",
       +"node" => "winrm://roddypiper@localhost:5985",
       +"result" => {"_error"=>{"details"=>{}, "issue_code"=>"CONNECT_ERROR", "kind"=>"puppetlabs.tasks/connect-error", "msg"=>"Failed to connect to http://localhost:5985/wsman: [WSMAN ERROR CODE: 2147746132]: <f:WSManFault Code='2147746132' Machine='localhost' xmlns:f='http://schemas.microsoft.com/wbem/wsman/1/wsmanfault'><f:Message>The WSMan service could not launch a host process to process the given request.  Make sure the WSMan provider host server and proxy are properly registered. </f:Message></f:WSManFault>"}},
       +"status" => "failure",
     # ./spec/integration/apply_spec.rb:274:in `block (4 levels) in <top (required)>'
  3) apply over winrm on Appveyor with Puppet Agents when running against puppet 5 does not create Boltdir
     Failure/Error: expect(result[0]).to include('status' => 'success')
       expected {"node" => "winrm://roddypiper@localhost:5985", "result" => {"_error" => {"details" => {}, "issue_code" => "CON... host server and proxy are properly registered. </f:Message></f:WSManFault>"}}, "status" => "failure"} to include {"status" => "success"}
       Diff:
       @@ -1,2 +1,4 @@
       -"status" => "success",
       +"node" => "winrm://roddypiper@localhost:5985",
       +"result" => {"_error"=>{"details"=>{}, "issue_code"=>"CONNECT_ERROR", "kind"=>"puppetlabs.tasks/connect-error", "msg"=>"Failed to connect to http://localhost:5985/wsman: [WSMAN ERROR CODE: 2147746132]: <f:WSManFault Code='2147746132' Machine='localhost' xmlns:f='http://schemas.microsoft.com/wbem/wsman/1/wsmanfault'><f:Message>The WSMan service could not launch a host process to process the given request.  Make sure the WSMan provider host server and proxy are properly registered. </f:Message></f:WSManFault>"}},
       +"status" => "failure",
     # ./spec/integration/apply_spec.rb:274:in `block (4 levels) in <top (required)>'
Finished in 4 minutes 28.8 seconds (files took 5.56 seconds to load)
6 examples, 3 failures



 Comments   
Comment by Cas Donoghue [ 2019/03/26 ]

Not sure if it is related but there I have seen a timeout error for winrm + sslĀ https://ci.appveyor.com/project/puppetlabs/bolt/builds/23351497/job/y7qbtwld137ds75j

 
Failures:
  1) Bolt::Transport::WinRM connecting over SSL executes a command on a host
     Failure/Error:
       output = @session.run(command) do |stdout, stderr|
         result_output.stdout << stdout
         @logger.debug { "stdout: #{stdout}" }
         result_output.stderr << stderr
         @logger.debug { "stderr: #{stderr}" }
       end
     HTTPClient::SendTimeoutError:
       execution expired
     # ./.bundle/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:515:in `query'
     # ./.bundle/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:177:in `query'
     # ./.bundle/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient.rb:1242:in `do_get_block'
     # ./.bundle/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient.rb:1019:in `block in do_request'
     # ./.bundle/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient.rb:1133:in `protect_keep_alive_disconnected'
     # ./.bundle/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient.rb:1014:in `do_request'
     # ./.bundle/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient.rb:856:in `request'
     # ./.bundle/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient.rb:765:in `post'
     # ./.bundle/ruby/2.5.0/gems/winrm-2.3.1/lib/winrm/http/transport.rb:176:in `send_request'
     # ./.bundle/ruby/2.5.0/gems/winrm-2.3.1/lib/winrm/shells/power_shell.rb:107:in `block in send_command'
     # ./.bundle/ruby/2.5.0/gems/winrm-2.3.1/lib/winrm/psrp/message_fragmenter.rb:51:in `fragment'
     # ./.bundle/ruby/2.5.0/gems/winrm-2.3.1/lib/winrm/shells/power_shell.rb:104:in `send_command'
     # ./.bundle/ruby/2.5.0/gems/winrm-2.3.1/lib/winrm/shells/base.rb:129:in `with_command_shell'
     # ./.bundle/ruby/2.5.0/gems/winrm-2.3.1/lib/winrm/shells/base.rb:79:in `run'
     # ./lib/bolt/transport/winrm/connection.rb:114:in `execute'
     # ./lib/bolt/transport/winrm.rb:87:in `block in run_command'
     # ./lib/bolt/transport/winrm.rb:69:in `with_connection'
     # ./lib/bolt/transport/winrm.rb:86:in `run_command'
     # ./spec/bolt/transport/winrm_spec.rb:154:in `block (3 levels) in <top (required)>'
Finished in 7 minutes 45 seconds (files took 5.07 seconds to load)
860 examples, 1 failure, 2 pending
Failed examples:
rspec ./spec/bolt/transport/winrm_spec.rb:153 # Bolt::Transport::WinRM connecting over SSL executes a command on a host
 

Comment by Ethan Brown [ 2019/03/26 ]

Don't think that it's the same, like what we see in https://ci.appveyor.com/project/puppetlabs/bolt/builds/23295542/job/1l58h2g84vmve3md

Failures:
  1) Bolt::Transport::WinRM with an open connection when determining result fails for PowerShell terminating errors:  Correct syntax bad command (CommandNotFoundException)
     Failure/Error: raise Bolt::Node::FileError.new(e.message, 'WRITE_ERROR')
     Bolt::Node::FileError:
       execution expired
     # ./lib/bolt/transport/winrm/connection.rb:156:in `rescue in write_remote_file_winrm'
     # ./lib/bolt/transport/winrm/connection.rb:152:in `write_remote_file_winrm'
     # ./lib/bolt/transport/winrm/connection.rb:148:in `write_remote_file'
     # ./lib/bolt/transport/winrm/connection.rb:216:in `write_remote_executable'
     # ./lib/bolt/transport/winrm.rb:97:in `block (2 levels) in run_script'
     # ./lib/bolt/transport/winrm/connection.rb:200:in `with_remote_tempdir'
     # ./lib/bolt/transport/winrm.rb:96:in `block in run_script'
     # ./lib/bolt/transport/winrm.rb:69:in `with_connection'
     # ./lib/bolt/transport/winrm.rb:95:in `run_script'
     # ./spec/bolt/transport/winrm_spec.rb:833:in `block (6 levels) in <top (required)>'
     # ./spec/lib/bolt_spec/files.rb:16:in `block in with_tempfile_containing'
     # ./spec/lib/bolt_spec/files.rb:13:in `with_tempfile_containing'
     # ./spec/bolt/transport/winrm_spec.rb:832:in `block (5 levels) in <top (required)>'
     # ------------------
     # --- Caused by: ---
     # HTTPClient::ReceiveTimeoutError:
     #   execution expired
     #   ./.bundle/ruby/2.5.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:881:in `read_body_length'
Finished in 6 minutes 27 seconds (files took 5.34 seconds to load)
925 examples, 1 failure, 2 pending

Comment by Ethan Brown [ 2019/04/09 ]

This ticket also addressed a few additional failure modes:

  • Timeout connecting to curl website to download CA bundle
  • Timeout connecting to Forge to install Puppetfile

Both of these scenarios now have timeouts.

Unable to reproduce any failures while testing - though the next time a failure occurs there should be additional information in the logs.

Generated at Mon Dec 09 08:14:23 PST 2019 using JIRA 7.7.1#77002-sha1:e75ca93d5574d9409c0630b81c894d9065296414.