kerberos: Bad HTTP response returned from server. Code 400

[jn.b...@gmail.com]

Hi there

Never had this error before, and also Google could not help me so far.

When I create a new virtualenv and install pip modules, I get the mentioned error when I try to manage Windows hosts with Ansible.
I'm on debian 8.9.
Steps to reproduce:

cd ~
virtualenv venv_ansible
. venv_ansible/bin/activate

(venv_ansible): pip install --upgrade pip
(venv_ansible): pip install --upgrade setuptools
(venv_ansible): pip install --upgrade xmltodict
(venv_ansible): pip install --upgrade pywinrm
(venv_ansible): pip install --upgrade requests_kerberos
(venv_ansible): pip install --upgrade pycrypto
(venv_ansible): pip install ansible

(venv_ansible): pip list
ansible (2.4.3.0)
asn1crypto (0.24.0)
bcrypt (3.1.4)
certifi (2018.1.18)
cffi (1.11.5)
chardet (3.0.4)
cryptography (2.1.4)
enum34 (1.1.6)
idna (2.6)
ipaddress (1.0.19)
Jinja2 (2.10)
MarkupSafe (1.0)
ntlm-auth (1.0.6)
paramiko (2.4.0)
pip (9.0.1)
pyasn1 (0.4.2)
pycparser (2.18)
pycrypto (2.6.1)
pykerberos (1.2.1)
PyNaCl (1.2.1)
pywinrm (0.3.0)
PyYAML (3.12)
requests (2.18.4)
requests-kerberos (0.12.0)
requests-ntlm (1.1.0)
setuptools (38.5.1)
six (1.11.0)
urllib3 (1.22)
xmltodict (0.11.0)

(venv_ansible): vi hosts

--------------------------------------------
[windows]
server1.domain.local

[all:vars]
ansible_port=5985
ansible_user=userid@DOMAIN.LOCAL
ansible_connection=winrm
ansible_winrm_server_cert_validation=ignore
ansible_winrm_transport=kerberos
ansible_winrm_operation_timeout_sec=60
ansible_winrm_read_timeout_sec=70
--------------------------------------------

(venv_ansible): kinit userid@DOMAIN.LOCAL

(venv_ansible): ansible -m win_ping -i hosts windows -vvvvv

ansible 2.4.3.0
  config file = None
  configured module search path = [u'/home/userid/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /home/userid/venv_ansible/local/lib/python2.7/site-packages/ansible
  executable location = /home/userid/venv_ansible/bin/ansible
  python version = 2.7.9 (default, Jun 29 2016, 13:08:31) [GCC 4.9.2]
No config file found; using defaults
setting up inventory plugins
Parsed /home/userid/hosts inventory source with ini plugin
Loading callback plugin minimal of type stdout, v2.0 from /home/userid/venv_ansible/local/lib/python2.7/site-packages/ansible/plugins/callback/minimal.pyc
META: ran handlers
Using module file /home/userid/venv_ansible/local/lib/python2.7/site-packages/ansible/modules/windows/win_ping.ps1
<server1.DOMAIN.LOCAL> ESTABLISH WINRM CONNECTION FOR USER: userid@DOMAIN.LOCAL on PORT 5985 TO server1.domain.local
checking if winrm_host server1.domain.local is an IPv6 address
<server1.DOMAIN.LOCAL> WINRM CONNECT: transport=kerberos endpoint=http://server1.domain.local:5985/wsman
<server1.DOMAIN.LOCAL> WINRM CONNECTION ERROR: Bad HTTP response returned from server. Code 400
Traceback (most recent call last):
  File "/home/userid/venv_ansible/local/lib/python2.7/site-packages/ansible/plugins/connection/winrm.py", line 240, in _winrm_connect
    self.shell_id = protocol.open_shell(codepage=65001)  # UTF-8
  File "/home/userid/venv_ansible/local/lib/python2.7/site-packages/winrm/protocol.py", line 157, in open_shell
    res = self.send_message(xmltodict.unparse(req))
  File "/home/userid/venv_ansible/local/lib/python2.7/site-packages/winrm/protocol.py", line 242, in send_message
    raise ex
WinRMTransportError: Bad HTTP response returned from server. Code 400

server1.domain.local | UNREACHABLE! => {
    "changed": false,
    "msg": "kerberos: Bad HTTP response returned from server. Code 400",
    "unreachable": true
}



On the same machine, I have an older virtualenv which is working fine, the only difference are some module versions:

(venv_ansible_ok): pip list
ansible (2.4.3.0)
asn1crypto (0.24.0)
bcrypt (3.1.4)
certifi (2017.4.17)
cffi (1.11.4)
chardet (3.0.4)
cryptography (2.1.4)
enum34 (1.1.6)
idna (2.6)
ipaddress (1.0.19)
Jinja2 (2.10)
MarkupSafe (1.0)
ntlm-auth (1.0.4)
ordereddict (1.1)
paramiko (2.4.0)
pip (9.0.1)
pyasn1 (0.4.2)
pycparser (2.18)
pycrypto (2.6.1)
pykerberos (1.1.14)
PyNaCl (1.2.1)
pywinrm (0.2.2)
PyYAML (3.12)
requests (2.18.1)
requests-kerberos (0.11.0)
requests-ntlm (1.0.0)
setuptools (38.5.1)
six (1.11.0)
urllib3 (1.21.1)
xmltodict (0.11.0)

I think it's just a bug (once again...) in a module, but I have no clue in which module or why.
So I even cannot raise an issue at the moment.

Any idea?

Thank you and regards
jn

[Jordan Borean]

Are you able to try port 5986 and see if that works. Potentially port 5985 is failing because the encryption process is creating a bad request causing the 400 but it would be good to know if your setup works with HTTPS where WinRM encryption isn't happening.

Thanks

Jordan

[J Hawkesworth]

Just wondering if this is a transient error? I have occasionally had problems when the windows host is applying windows updates or running ngen to recompile dotnet code following installation of an upgrade to dotnet framework.

Jon

[matt...@redhat.com]

On a related note: maybe try just tweaking the existing setup to use `ansible_winrm_message_encryption=never` on your Windows host(s) in the inventory or via `-e` to prove if it's related to the new message encryption support. You've clearly been running unencrypted in the past- we'll leave the discussion of that being a good idea for another thread ;) but disabling message encryption that way should put you back to exactly the way it was working before.

-Matt

[jn.b...@gmail.com]

It isn't a transient error, it occurs always in this setup with the mentioned module versions. Tested with different windows versions.

Everything is working find with your suggestions:
ansible_port=5986
and also with
ansible_winrm_message_encryption=never

So problem solved for me, thank you all very much.

But still, either it is a bug and we should report it, or the Ansible documentation should be updated.


Regards
jn

[Jordan Borean]

Yes, this means the message encryption done with Kerberos is failing for whatever reason and producing a malformed message. This encryption support was added in pywinrm 0.3.0 and it would be great to find out what may been happening to cause it to fail  as it is quite important to use it when running over http.

To help with us replicating the issue are you able to share with us as much information on the hosts as possible like;

* The version of Windows you are using
* Run 'krb5-config --version' on the Ansible controller and let us know the version
* What OS the Ansible controller is on
* A copy of '/etc/krb5.conf' on the Ansible controller (feel free to blank out the hostname)
* The output of 'klist -v' when run on the Ansible controller after connecting to the host. This tells us what type of encryption is being uses for the principal

Thanks

Jordan

[jn.b...@gmail.com]

I hope I got all:



(venv_ansible)[userid@ansiblehost ~/ansible_test]$ pip list

(venv_ansible)[userid@ansiblehost ~/ansible_test]$ cat hosts

[windows]
server2016.domain.local      #windows 2016
server2012r2.domain.local    #windows 2012 r2

[all:vars]
ansible_port=5985
ansible_user=use...@DOMAIN.LOCAL

ansible_connection=winrm
ansible_winrm_server_cert_validation=ignore
ansible_winrm_transport=kerberos
ansible_winrm_operation_timeout_sec=60
ansible_winrm_read_timeout_sec=70

(venv_ansible)[userid@ansiblehost ~/ansible_test]$ ansible -m win_ping -i hosts windows -vvvvvv

ansible 2.4.3.0
  config file = None
  configured module search path = [u'/home/userid/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /home/userid/venv_ansible/local/lib/python2.7/site-packages/ansible
  executable location = /home/userid/venv_ansible/bin/ansible
  python version = 2.7.9 (default, Jun 29 2016, 13:08:31) [GCC 4.9.2]
No config file found; using defaults
setting up inventory plugins

Parsed /home/userid/ansible_test/hosts inventory source with ini plugin

Loading callback plugin minimal of type stdout, v2.0 from /home/userid/venv_ansible/local/lib/python2.7/site-packages/ansible/plugins/callback/minimal.pyc
META: ran handlers
Using module file /home/userid/venv_ansible/local/lib/python2.7/site-packages/ansible/modules/windows/win_ping.ps1

Using module file /home/userid/venv_ansible/local/lib/python2.7/site-packages/ansible/modules/windows/win_ping.ps1
<server2016.domain.local> ESTABLISH WINRM CONNECTION FOR USER: use...@DOMAIN.LOCAL on PORT 5985 TO server2016.domain.local
checking if winrm_host server2016.domain.local is an IPv6 address
<server2012r2.domain.local> ESTABLISH WINRM CONNECTION FOR USER: use...@DOMAIN.LOCAL on PORT 5985 TO server2012r2.domain.local
<server2016.domain.local> WINRM CONNECT: transport=kerberos endpoint=http://server2016.domain.local:5985/wsman
checking if winrm_host server2012r2.domain.local is an IPv6 address
<server2012r2.domain.local> WINRM CONNECT: transport=kerberos endpoint=http://server2012r2.domain.local:5985/wsman
<server2016.domain.local> WINRM CONNECTION ERROR: Bad HTTP response returned from server. Code 400

Traceback (most recent call last):
  File "/home/userid/venv_ansible/local/lib/python2.7/site-packages/ansible/plugins/connection/winrm.py", line 240, in _winrm_connect
    self.shell_id = protocol.open_shell(codepage=65001)  # UTF-8
  File "/home/userid/venv_ansible/local/lib/python2.7/site-packages/winrm/protocol.py", line 157, in open_shell
    res = self.send_message(xmltodict.unparse(req))
  File "/home/userid/venv_ansible/local/lib/python2.7/site-packages/winrm/protocol.py", line 242, in send_message
    raise ex
WinRMTransportError: Bad HTTP response returned from server. Code 400

server2016.domain.local | UNREACHABLE! => {

    "changed": false,
    "msg": "kerberos: Bad HTTP response returned from server. Code 400",
    "unreachable": true
}

<server2012r2.domain.local> WINRM CONNECTION ERROR: Bad HTTP response returned from server. Code 400

Traceback (most recent call last):
  File "/home/userid/venv_ansible/local/lib/python2.7/site-packages/ansible/plugins/connection/winrm.py", line 240, in _winrm_connect
    self.shell_id = protocol.open_shell(codepage=65001)  # UTF-8
  File "/home/userid/venv_ansible/local/lib/python2.7/site-packages/winrm/protocol.py", line 157, in open_shell
    res = self.send_message(xmltodict.unparse(req))
  File "/home/userid/venv_ansible/local/lib/python2.7/site-packages/winrm/protocol.py", line 242, in send_message
    raise ex
WinRMTransportError: Bad HTTP response returned from server. Code 400

server2012r2.domain.local | UNREACHABLE! => {

    "changed": false,
    "msg": "kerberos: Bad HTTP response returned from server. Code 400",
    "unreachable": true
}

(venv_ansible)[userid@ansiblehost ~/ansible_test]$ krb5-config --version
Kerberos 5 release 1.12.1



(venv_ansible)[userid@ansiblehost ~/ansible_test]$ cat /etc/debian_version
8.9


(venv_ansible)[userid@ansiblehost ~/ansible_test]$ cat /etc/krb5.conf
[logging]
 default = FILE:/var/log/krb5libs.log
 kdc = FILE:/var/log/krb5kdc.log
 admin_server = FILE:/var/log/kadmind.log

[libdefaults]
 default_realm = MANAGEMENT.LOCAL
 default_tkt_enctypes = arcfour-hmac-md5 des-cbc-crc des-cbc-md5
 default_tgs_enctypes = arcfour-hmac-md5 des-cbc-crc des-cbc-md5
 allow_weak_crypto = true
 udp_preference_limit = 1
 kdc_timeout = 1000
 forwardable = true

[realms]
  MANAGEMENT.LOCAL = {
   default_domain = MANAGEMENT.LOCAL
  }

[domain_realm]
 .management.local = MANAGEMENT.LOCAL
 management.local = MANAGEMENT.LOCAL


[appdefaults]
 pam = {
   ticket_lifetime = 36000
   renew_lifetime = 36000
   forwardable = true
 }

 
(venv_ansible)[userid@ansiblehost ~/ansible_test]$ klist -e

 Ticket cache: FILE:/tmp/krb5cc_1000019852
Default principal: use...@DOMAIN.LOCAL

Valid starting       Expires              Service principal
03/02/2018 09:00:41  03/02/2018 19:00:41  krbtgt/DOMAIN...@DOMAIN.LOCAL
        renew until 03/03/2018 09:00:39, Etype (skey, tkt): arcfour-hmac, aes256-cts-hmac-sha1-96
03/02/2018 09:00:53  03/02/2018 19:00:41  HTTP/server2016.domain.local@
        renew until 03/03/2018 09:00:39, Etype (skey, tkt): arcfour-hmac, arcfour-hmac
03/02/2018 09:00:53  03/02/2018 19:00:41  HTTP/server2016....@DOMAIN.LOCAL
        renew until 03/03/2018 09:00:39, Etype (skey, tkt): arcfour-hmac, arcfour-hmac
03/02/2018 09:00:53  03/02/2018 19:00:41  HTTP/server2012r2.domain.local@
        renew until 03/03/2018 09:00:39, Etype (skey, tkt): arcfour-hmac, arcfour-hmac
03/02/2018 09:00:53  03/02/2018 19:00:41  HTTP/server2012r2...@DOMAIN.LOCAL
        renew until 03/03/2018 09:00:39, Etype (skey, tkt): arcfour-hmac, arcfour-hmac


yes, the ansible controller is member of another domain as the windows servers. This wasn't a problem and also shouldn't be in this case.

jn

[Jordan Borean]

Without testing it I believe there may be an issue with the RC4 encryption that is being used. Will have to try it out but that is a pretty old protocol and believed to be broken. While we should still look at fixing it, you should look at adding in one of the AES types on your krb5.conf file http://web.mit.edu/kerberos/krb5-1.12/doc/admin/enctypes.html. I believe you need a dc on Server 2008 or newer.

Thanks for the information you provided.

Jordan

[matt...@redhat.com]

Yep, the non-default encryption setting is almost certainly the issue. Can you file a bug on https://github.com/02strich/pykerberos? No promises that we'll get to it, but I have a couple ideas as to what might be causing it. I *think* the fix could be pretty simple (there's a code path in there that never got tested because the default AES encryption settings never hit it). 

-Matt

[Leandro Padua]

Hi,

I had a similar issue and you guys were spot on.

Removing these lines solved my problem:

 default_tkt_enctypes = arcfour-hmac-md5 des-cbc-crc des-cbc-md5
 default_tgs_enctypes = arcfour-hmac-md5 des-cbc-crc des-cbc-md5

Thanks.

Leo