WinRM service is a service provided by Windows to enable remote access a Windows system. It is similar to what SSH is for *nix. And it is frequently used in applications which want to automate process or accessing remote Windows system and perform actions on them. Ruby also provided the WinRM gem which is an implementation of the WinRM service.
When using WinRM gem, one may often want to use :negotiate as the transport protocol for authentication. This transport will negotiate using different security mechanisms depends on the setting. These mechanisms include Kerberos, NTLM, Basic etc. But sometimes problems may occur during the negotiation. It would be credential issue, network issue, proxy issue etc. Today we are going to talk about an issue while using the :negotiate transport.
The issue is that a client is establishing some connection with a remote server using WinRM, and when the request is sent to the server, the client expects a 401 HTTP status code returned so that it can send more challenge data for authentication. However, a 200 HTTP status code is returned and the negotiate fails. The stacktrace looks like:
NoMethodError: undefined method `split' for nil:NilClass
from /home/cobalt/.rvm/gems/ruby-2.2.2/gems/winrm-1.7.3/lib/winrm/http/transport.rb:226:in `init_auth'
from /home/cobalt/.rvm/gems/ruby-2.2.2/gems/winrm-1.7.3/lib/winrm/http/transport.rb:166:in `send_request'
from /home/cobalt/.rvm/gems/ruby-2.2.2/gems/winrm-1.7.3/lib/winrm/winrm_service.rb:489:in `send_message'
from /home/cobalt/.rvm/gems/ruby-2.2.2/gems/winrm-1.7.3/lib/winrm/winrm_service.rb:390:in `run_wql'
from /home/cobalt/.rvm/gems/ruby-2.2.2/gems/winrm-1.7.3/lib/winrm/command_executor.rb:186:in `os_version'
from /home/cobalt/.rvm/gems/ruby-2.2.2/gems/winrm-1.7.3/lib/winrm/command_executor.rb:145:in `code_page'
from /home/cobalt/.rvm/gems/ruby-2.2.2/gems/winrm-1.7.3/lib/winrm/command_executor.rb:72:in `block in open'
from /home/cobalt/.rvm/gems/ruby-2.2.2/gems/winrm-1.7.3/lib/winrm/command_executor.rb:218:in `retryable'
from /home/cobalt/.rvm/gems/ruby-2.2.2/gems/winrm-1.7.3/lib/winrm/command_executor.rb:71:in `open'
from (irb):20
from /home/cobalt/.rvm/gems/ruby-2.2.2/gems/railties-4.2.1/lib/rails/commands/console.rb:110:in `start'
from /home/cobalt/.rvm/gems/ruby-2.2.2/gems/railties-4.2.1/lib/rails/commands/console.rb:9:in `start'
from /home/cobalt/.rvm/gems/ruby-2.2.2/gems/railties-4.2.1/lib/rails/commands/commands_tasks.rb:68:in `console'
from /home/cobalt/.rvm/gems/ruby-2.2.2/gems/railties-4.2.1/lib/rails/commands/commands_tasks.rb:39:in `run_command!'
from /home/cobalt/.rvm/gems/ruby-2.2.2/gems/railties-4.2.1/lib/rails/commands.rb:17:in `<top (required)>'
from bin/rails:4:in `require'
from bin/rails:4:in `<main>'2.2.2 :021 >
At first glance, the issue seems similar to the one reported at `init_auth': undefined method `split' for nil:NilClass #208.It says it may be a proxy issue and proxy settings need to be checked. But the truth is that in this case, the connection between the client and the server is not blocked. See the tcpdump output.
12:04:08.421368 IP d8b5d56cba65.53166 > some.server.wsman: Flags [P.], seq 1:340, ack 1, win 229, options [nop,nop,TS val 1316187725 ecr 79780711], length 339
0x0000: 4500 0187 7600 4000 4006 d339 0400 0005 E...v.@.@..9....
0x0010: 0acd e165 cfae 1761 acd8 1be3 dcb5 199e ...e...a........
0x0020: 8018 00e5 f1b0 0000 0101 080a 4e73 6e4d ............NsnM
0x0030: 04c1 5b67 504f 5354 202f 7773 6d61 6e20 ..[gPOST./wsman.
0x0040: 4854 5450 2f31 2e31 0d0a 4175 7468 6f72 HTTP/1.1..Author
0x0050: 697a 6174 696f 6e3a 204e 6567 6f74 6961 ization:.Negotia
0x0060: 7465 2054 6c52 4d54 564e 5455 4141 4241 te.TlRMTVNTUAABA
0x0070: 4141 414e 3449 4934 4151 4142 4141 6741 AAAN4II4AQABAAgA
0x0080: 4141 4141 4141 4141 4351 4141 4142 4462 AAAAAAAACQAAABDb
0x0090: 334a 775a 4468 694e 5751 314e 6d4e 6959 3JwZDhiNWQ1NmNiY
0x00a0: 5459 310d 0a43 6f6e 7465 6e74 2d54 7970 TY1..Content-Typ
0x00b0: 653a 2061 7070 6c69 6361 7469 6f6e 2f73 e:.application/s
0x00c0: 6f61 702b 786d 6c3b 6368 6172 7365 743d oap+xml;charset=
0x00d0: 5554 462d 380d 0a55 7365 722d 4167 656e UTF-8..User-Agen
0x00e0: 743a 2052 7562 7920 5769 6e52 4d20 436c t:.Ruby.WinRM.Cl
0x00f0: 6965 6e74 2028 322e 372e 312c 2072 7562 ient.(2.7.1,.rub
0x0100: 7920 322e 322e 3220 2832 3031 352d 3034 y.2.2.2.(2015-04
0x0110: 2d31 3329 290d 0a41 6363 6570 743a 202a -13))..Accept:.*
0x0120: 2f2a 0d0a 4461 7465 3a20 5475 652c 2030 /*..Date:.Tue,.0
0x0130: 3720 4d61 7220 3230 3137 2031 323a 3034 7.Mar.2017.12:04
0x0140: 3a30 3820 474d 540d 0a43 6f6e 7465 6e74 :08.GMT..Content
0x0150: 2d4c 656e 6774 683a 2030 0d0a 486f 7374 -Length:.0..Host
0x0160: 3a20 706f 6b63 7065 7573 6170 3032 2e63 :.po0000000000.c
0x0170: 6f72 702e 6162 7363 2e6c 6f63 616c 3a35 orp.0000.local:5
0x0180: 3938 350d 0a0d 0a 985....
12:04:08.516497 IP some.server.wsman > d8b5d56cba65.53166: Flags [P.], seq 1:39, ack 340, win 256, options [nop,nop,TS val 79780721 ecr 1316187725], length 38
0x0000: 4500 005a 7f05 4000 7d06 8e61 0acd e165 E..Z..@.}..a...e
0x0010: 0400 0005 1761 cfae dcb5 199e acd8 1d36 .....a.........6
0x0020: 8018 0100 11f4 0000 0101 080a 04c1 5b71 ..............[q
0x0030: 4e73 6e4d 4854 5450 2f31 2e31 2032 3030 NsnMHTTP/1.1.200
0x0040: 204f 4b0d 0a43 6f6e 7465 6e74 2d4c 656e .OK..Content-Len
0x0050: 6774 683a 2030 0d0a 0d0a gth:.0....
The server did return a response with HTTP status code 200. So the cause of proxy is ruled out.
What's going wrong? The response returned by the server using WinRM has an empty HTTP header item which doesn't contain the WWW-AUthenticate token.
The port 5985 is open when testing using telnet. So the next thing to check is whether the WinRM service is running properly on the server, from another server, below command is issued.
test-wsman some.server
OK. The output shows it's getting 'ACCESS DENIED', what's the problem? Why this error? This means the service at that side is expecting some authentication to be made. This is not required when the WinRM service is running properly and the above command is issued. It should return
So why not check which process is listening at port 5985 on the remote server? Login to the server and issue below command.
netstat -a -b
And look for port 5985. And we see below output
TCP 0.0.0.0:5985 SERVER:0 LISTENING [SOMEAPP.exe]
TCP 0.0.0.0:5986 SERVER:0 LISTENING [SOMEAPP.exe]
Some other application is using this port. That's why above weird behavior occurs. WinRM service will use this port by default, so the WinRM gem and test-wsman will all try to connect to this port.
Once is the issue is found., the resolution should be easy.
