v3 PKI token requests result in 500 error when run in apache

[Jeremy Agee]

A 500 Internal Server Error is generated when requests are issued to /v3/auth/tokens

mkdir /var/www/cgi-bin/keystone
ln /usr/share/keystone/keystone.wsgi /var/www/cgi-bin/keystone/main
ln /usr/share/keystone/keystone.wsgi /var/www/cgi-bin/keystone/admin

/etc/httpd/conf.d/wsgi-keystone.conf
Listen 5000
<VirtualHost *:5000>
WSGIScriptAlias / /var/www/cgi-bin/keystone/main

<Location />
AuthType None
</Location>
</VirtualHost>

Listen 35357
<VirtualHost *:35357>
WSGIScriptAlias / /var/www/cgi-bin/keystone/admin

<Location />
AuthType None
</Location>
</VirtualHost>

Using version:
python-keystone-2013.2-1.el6ost

keystone.conf
[signing]
token_format = PKI

testuser:
keystone user-create --name tester --pass tester --email <email address hidden>
keystone role-create --name tester
keystone tenant-create --name tester
keystone user-role-add --user-id {USER_ID} --role-id {ROLE_ID} --tenant-id {TENANT_ID}

Request:
curl -H "Content-type: application/json" -d '{"auth": {"identity": {"methods": ["password"], "password": {"user": {"domain": {"name": "Default"}, "name": "tester","password": "tester"}}}, "scope": {"project": {"domain": {"name": "Default"},"name": "tester"}}}}' http://127.0.0.1:5000/v3/auth/tokens

Note:
The issues is not present if UUID tokens are used.

[Dolph Mathews (dolph)]

There's not really any information here to debug a 500 (a backtrace should definitely be logged for all 500s). My best blind guess is that you didn't provide certificates (for example, `$ keystone-manage pki_setup`) or there's something wrong with the openssl installation (version <1.0?).

[Jeremy Agee (jagee)]

Im not seeing a backtrace in any logs but hopefully this will provide a clearer picture into whats happening. It looks like we are dealing with something getting truncated between keystone and httpd.

If i submit a token request but dont get catalog data i get a valid token response.

curl -i --negotiate -u : -H "Content-type: application/json" -d '{"auth": {"identity": {"methods": []},"scope": {"project": {"domain": {"name": "Default"},"name": "tester"}}}}' http://keystone-krb5.lab.eng.rdu2.redhat.com:5000/v3/auth/tokens?nocatalog

HTTP/1.1 201 Created
Date: Mon, 02 Dec 2013 17:08:23 GMT
Server: Apache/2.2.15 (Red Hat)
X-Subject-Token: MIIDlgYJKoZIhvcNAQcCoIIDhzCCA4MCAQExCTAHBgUrDgMCGjCCAewGCSqGSIb3DQEHAaCCAd0EggHZeyJ0b2tlbiI6IHsibWV0aG9kcyI6IFtdLCAicm9sZXMiOiBbeyJpZCI6ICI5YzVjZTExN2YzNDM0MDM4OGY3MWZiYWQ4ZWFmMDAxOSIsICJuYW1lIjogInRlc3RlciJ9XSwgImJpbmQiOiB7ImtlcmJlcm9zIjogInRlc3RlciJ9LCAiZXhwaXJlc19hdCI6ICIyMDEzLTEyLTAzVDE3OjA4OjI0LjY0OTgwN1oiLCAicHJvamVjdCI6IHsiZG9tYWluIjogeyJpZCI6ICJkZWZhdWx0IiwgIm5hbWUiOiAiRGVmYXVsdCJ9LCAiaWQiOiAiN2M3ODNhNjE1NGVkNGE4OWEyZTJkMjBhYmUyYmE4MzMiLCAibmFtZSI6ICJ0ZXN0ZXIifSwgImV4dHJhcyI6IHt9LCAidXNlciI6IHsiZG9tYWluIjogeyJpZCI6ICJkZWZhdWx0IiwgIm5hbWUiOiAiRGVmYXVsdCJ9LCAiaWQiOiAiNTM2ZjRjYjA1N2E5NGNjZTlhZTNjZGEyYjUyYmIzOTYiLCAibmFtZSI6ICJ0ZXN0ZXIifSwgImlzc3VlZF9hdCI6ICIyMDEzLTEyLTAyVDE3OjA4OjI0LjY0OTgzOVoifX0xggGBMIIBfQIBATBcMFcxCzAJBgNVBAYTAlVTMQ4wDAYDVQQIDAVVbnNldDEOMAwGA1UEBwwFVW5zZXQxDjAMBgNVBAoMBVVuc2V0MRgwFgYDVQQDDA93d3cuZXhhbXBsZS5jb20CAQEwBwYFKw4DAhowDQYJKoZIhvcNAQEBBQAEggEAHnallvno62RoCNinvEuEqFUcw94Nt06B27H+kj1EVi1utLqhGGP1MUP8CzigOCxG8-8KYBx1UDCz32DrbcxyO-iiFCeJaKzdS4nXCjDckRJBkyOylVJ2P-x3dy7UrMet97C22Pinu8uCACVA6idyaCQ5l9dyvoN-3TNXG9GTv3IJe8oz8wdAjgm62fjfG8IWwyDv8wCh1-b7UNegmesv-8ibun1nJaAdY-CiZQUSF18dZ3HGtKFFt8YtC29b7NyOTiPU3X5yYXLX3aa0UdMP07xMbEXzU5UXrCOmaMhmNyqmbzXil53GvwyoqnGNFPZqRwozRGe2F3niCd+28vTy8g==
Vary: X-Auth-Token
Content-Length: 473
Connection: close
Content-Type: application/json

{"token": {"methods": [], "roles": [{"id": "9c5ce117f34340388f71fbad8eaf0019", "name": "tester"}], "bind": {"kerberos": "tester"}, "expires_at": "2013-12-03T17:08:24.649807Z", "project": {"domain": {"id": "default", "name": "Default"}, "id": "7c783a6154ed4a89a2e2d20abe2ba833", "name": "tester"}, "extras": {}, "user": {"domain": {"id": "default", "name": "Default"}, "id": "536f4cb057a94cce9ae3cda2b52bb396", "name": "tester"}, "issued_at": "2013-12-02T17:08:24.649839Z"}}

keystone.log
2013-12-02 12:08:24.668 6055 INFO sqlalchemy.engine.base.Engine [-] ('9aa72b9822c228933616c6b0673b4607', datetime.datetime(2013, 12, 3, 17, 8, 24, 649807), '{"token_data": {"token": {"methods": [], "roles": [{"id": "9c5ce117f34340388f71fbad8eaf0019", "name": "tester"}], "bind": {"kerberos": "tester"}, "expires_at": "2013-12-03T17:08:24.649807Z", "project": {"domain": {"id": "default", "name": "Default"}, "id": "7c783a6154ed4a89a2e2d20abe2ba833", "name": "tester"}, "extras": {}, "user": {"domain": {"id": "default", "name": "Default"}, "id": "536f4cb057a94cce9ae3cda2b52bb396", "name": "tester"}, "issued_at": "2013-12-02T17:08:24.649839Z"}}, "user": {"domain": {"id": "default", "name": "Default"}, "id": "536f4cb057a94cce9ae3cda2b52bb396"...

[Jeremy Agee (jagee)]

My last post was using kerberos external auth and not password auth like the original report. They both have the same behavior, sorry if that added any confusion. I originally hit this when testing kerberos but I can reproduce it with a password based auth setups as well.

[Jeremy Agee (jagee)]

It looks like when the catalog is present on the v3 token its over 8190 bytes. im hitting a httpd default size limit. This is why keystone is not showing any issue but we are seeing the 500. Its looking like settings such as LimitRequestFieldSize in apache will be required to be upped.

[Dolph Mathews (dolph)]

Was going to mark this as invalid, but the above configuration should definitely be documented.

[Eric Brown (ericwb)]

I had a similar problem when using PKI tokens with HTTPD keystone. But in my case Apache httpd returned a Bad Header response. I couldn't figure it out. It worked fine with UUID tokens, but not PKI. I did attempt to change the LimitRequestFieldSize, but it didn't help. I saw this problem on RHEL 6.4 with httpd 2.2.15.

Today, I tried to recreate the issue using Ubuntu and devstack (as my RHEL config is gone). I couldn't duplicate it. PKI tokens with httpd keystone appears to work fine.

[Mark Miller (mark-m-miller)]

I just ran into this problem so I think it is still valid. The problem definitely has to do with the PKI token size when using the Apache2 WSGI front end for Keystone. I played around with the token size by deleting the number of endpoints and found that the exact same REST API call which previously failed executed without the error. I contacted Graham Dumpleton on the mod_wsgi project and asked him if there were a way to increase the maximum size of the response header and received the following response:

"This is a hardwired limitation within the Apache function used by mod_wsgi to parse the response headers returned from a WSGI application running in daemon mode."

He does however have a fix up his sleeve and is thinking about making it.

[Mark Miller (mark-m-miller)]

By the way, here is the error as reported by Keystone:

[Thu Jan 16 22:44:08 2014] [info] Initial (No.1) HTTPS request received for child 70 (server d00-50-56-8e-75-82.cloudos.org:5000)
[Thu Jan 16 22:44:08 2014] [info] [client 192.168.124.2] mod_wsgi (pid=22969, process='keystone', application='d00-50-56-8e-75-82.cloudos.org:5000|'): Loading WSGI script '/etc/apache2/wsgi/keystone/main'.
[Thu Jan 16 22:44:09 2014] [error] [client 192.168.124.2] malformed header from script. Bad header=mVmOTdhMmUzIn0sIHsidXJsIjogImh: main
[Thu Jan 16 22:44:09 2014] [debug] mod_deflate.c(615): [client 192.168.124.2] Zlib: Compressed 592 to 377 : URL /v3/auth/tokens
[Thu Jan 16 22:44:09 2014] [debug] ssl_engine_kernel.c(1884): OpenSSL: Write: SSL negotiation finished successfully
[Thu Jan 16 22:44:09 2014] [info] [client 192.168.124.2] Connection closed to child 70 with standard shutdown (server d00-50-56-8e-75-82.cloudos.org:5000)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/71181
Committed: https://git.openstack.org/cgit/openstack/python-keystoneclient/commit/?id=3d6d749e6f0fef682a88758e1a2f6c9e8e7bd23c
Submitter: Jenkins
Branch: master

commit 3d6d749e6f0fef682a88758e1a2f6c9e8e7bd23c
Author: Adam Young <email address hidden>
Date: Tue Feb 4 20:43:07 2014 -0500

    Compressed Signature and Validation

    Allows for a new form of document signature.

    pkiz_sign will take data and encode it in a string that starts with
    the substring "PKIZ_". This prefix indicates that the data has been:
    1) Signed via PKI in Crypto Message Syntax (CMS) in binary (DER) format
    2) Compressed using zlib (comparable to gzip)
    3) urlsafe-base64 decoded

    This process is reversed to validate the data.

    middleware/auth_token.py will be capable of validating Keystone
    tokens that are marshalled in the new format. The current existing
    "PKI" tokens will continue to be identified with "MII", issued by
    default, and validated as well. It will require corresponding changes
    on the Keystone server to issue the new token format.

    A separate script for generating the sample
    data used in the unit tests,
    examples/pki/gen_cmsz.py,
    also serves as an example of how to
    call the API from Python code.

    Some of the sample data for the old tests had to be regenerated. A
    stray comma in one of the JSON files made for non-parsing JSON.

    Blueprint: compress-tokens
    Closes-Bug: #1255321

    Change-Id: Ia9a66ba3742da0bcd58c4c096b28cc8a66ad6569

[Atsuko Ito (yottatsa)]

I have another approach to this issue, reducing token size dramatically https://blueprints.launchpad.net/keystone/+spec/compact-pki-token

[Ruslan Kiianchuk (zoresvit)]

This should already be fixed since mod_wsgi version 4.1.0: https://github.com/GrahamDumpleton/mod_wsgi/blob/81674f7380fe2cf10919b726476a89a32442cf24/docs/release-notes/version-4.1.0.rst

"16. The maximum size that a response header/value can be that is returned from a WSGI application under daemon mode can now be configured. The default size has also now been increased from 8192 bytes to 32768 bytes. The name of the option to WSGIDaemonProcess to set the buffer size used is header-buffer-size."

[Steve Martinelli (stevemar)]

This was fixed when PKIZ was added to Keystone:
https://github.com/openstack/keystone/commit/063070f21ffc3345e2b25904ff4a1ae89f539c32

[Brant Knudson (blk-u)]

this isn't fixed by using pkiz tokens. pkiz tokens are smaller but if the catalog is large the tokens will still get to big and will fail when run in apache.