Error 500 when testing new v229 CF deployment


James Leavers
 

Hi,

I have just set up a fresh v229 install to do some testing with - the bosh deployment appeared to complete successfully and all the VMs are running, however anything after initial authentication fails with an error 500:

iMac:~ jim$ cf login
API endpoint: https://api.app.x.y

Email> admin

Password>
Authenticating...
OK

FAILED
Error finding available orgs
Server error, status code: 500, error code: 10001, message: An unknown error occurred.


API endpoint: https://api.app.x.y (API version: 2.47.0)
User: admin
No org or space targeted, use 'cf target -o ORG -s SPACE'

iMac:~ jim$ CF_TRACE=true cf orgs
Getting orgs as admin...


REQUEST: [2016-01-27T11:48:25Z]
GET /v2/organizations HTTP/1.1
Host: api.app.x.y
Accept: application/json
Authorization: [PRIVATE DATA HIDDEN]
Content-Type: application/json
User-Agent: go-cli 6.15.0+fa1bfe2 / darwin



RESPONSE: [2016-01-27T11:48:26Z]
HTTP/1.1 500 Internal Server Error
Content-Length: 99
Content-Type: application/json;charset=utf-8
Date: Wed, 27 Jan 2016 11:48:26 GMT
Server: nginx
X-Cf-Requestid: fbf3ba39-65fd-4e21-67a5-f3ba7f9c0330
X-Content-Type-Options: nosniff
X-Vcap-Request-Id: 471ad2c7-0e09-46a9-6a31-6fe5024a1084::f9173c33-ee11-4513-a124-6ab04a37484d

{
"error_code": "UnknownError",
"description": "An unknown error occurred.",
"code": 10001
}

FAILED
Server error, status code: 500, error code: 10001, message: An unknown error occurred.
FAILED
Server error, status code: 500, error code: 10001, message: An unknown error occurred.

I had a look in cloud_controller_ng.log on api_z1/0 & api_z2/0 and can see the requests failing as follows:

{"timestamp":1453833820.1395981,"message":"Started GET \"/v2/organizations\" for 86.152.144.203 with vcap-request-id: d44f2a12-873f-437f-7d2c-f261f503640f::1d2ea0bc-1a78-49ea-85ff-bfb9c11d2f2b at 2016-01-26 18:43:40 UTC","log_level":"info","source":"cc.api","data":{},"thread_id":47241509083720,"fiber_id":47241507190360,"process_id":5222,"file":"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/middleware/request_logs.rb","lineno":12,"method":"call"}
{"timestamp":1453833820.1408544,"message":"Request failed: 500: {\"code\"=>10001, \"description\"=>\"Neither PUB key nor PRIV key: header too long\", \"error_code\"=>\"CF-RSAError\", \"backtrace\"=>[\"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/cache/cf-uaa-lib-b1e11235dc6c/lib/uaa/token_coder.rb:51:in `initialize'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/cache/cf-uaa-lib-b1e11235dc6c/lib/uaa/token_coder.rb:51:in `new'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/cache/cf-uaa-lib-b1e11235dc6c/lib/uaa/token_coder.rb:51:in `normalize_options'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/cache/cf-uaa-lib-b1e11235dc6c/lib/uaa/token_coder.rb:158:in `initialize'\", \"/var/vcap/data/packages/cloud_controller_ng/e2284b8d57577947694deb55d61cbb3a2c87ac06.1-7f1e9cd9c57e152bf8c7a71d84131f5a43476974/cloud_controller_ng/lib/vcap/uaa_token_decoder.rb:62:in `new'\", \"/var/vcap/data/packages/cloud
_controller_ng/e2284b8d57577947694deb55d61cbb3a2c87ac06.1-7f1e9cd9c57e152bf8c7a71d84131f5a43476974/cloud_controller_ng/lib/vcap/uaa_token_decoder.rb:62:in `decode_token_with_key'\", \"/var/vcap/data/packages/cloud_controller_ng/e2284b8d57577947694deb55d61cbb3a2c87ac06.1-7f1e9cd9c57e152bf8c7a71d84131f5a43476974/cloud_controller_ng/lib/vcap/uaa_token_decoder.rb:53:in `decode_token_with_asymmetric_key'\", \"/var/vcap/data/packages/cloud_controller_ng/e2284b8d57577947694deb55d61cbb3a2c87ac06.1-7f1e9cd9c57e152bf8c7a71d84131f5a43476974/cloud_controller_ng/lib/vcap/uaa_token_decoder.rb:29:in `decode_token'\", \"/var/vcap/data/packages/cloud_controller_ng/e2284b8d57577947694deb55d61cbb3a2c87ac06.1-7f1e9cd9c57e152bf8c7a71d84131f5a43476974/cloud_controller_ng/lib/cloud_controller/security/security_context_configurer.rb:22:in `decode_token'\", \"/var/vcap/data/packages/cloud_controller_ng/e2284b8d57577947694deb55d61cbb3a2c87ac06.1-7f1e9cd9c57e152bf8c7a71d84131f5a43476974/cloud_controller_ng/li
b/cloud_controller/security/security_context_configurer.rb:10:in `configure'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/app/controllers/base/front_controller.rb:26:in `block in <class:FrontController>'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1610:in `block in compile!'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in `[]'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1014:in `block in process_route'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `catch'\", \"/var/vcap/packages/cloud
_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1012:in `process_route'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:965:in `block in filter!'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:965:in `each'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:965:in `filter!'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1083:in `block in dispatch!'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/ba
se.rb:1066:in `catch'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1081:in `dispatch!'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `block in call!'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `block in invoke'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `catch'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:1066:in `invoke'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.
0/gems/sinatra-1.4.6/lib/sinatra/base.rb:906:in `call!'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:894:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in
`call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/nulllogger.rb:9:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/head.rb:13:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:181:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sinatra-1.4.6/lib/sinatra/base.rb:2021:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/urlmap.rb:66:in `block in call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/urlm
ap.rb:50:in `each'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/urlmap.rb:50:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/middleware/request_logs.rb:21:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/middleware/vcap_request_id.rb:14:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/middleware/cors.rb:47:in `call_app'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/middleware/cors.rb:12:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/middleware/request_metrics.rb:12:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/rack-1.6.4/lib/rack/builder.rb:153:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/thin-1.6.3/lib/thin/connection.rb:86:in `block in pre_process'\", \"/var/vcap/packages/cloud_c
ontroller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/thin-1.6.3/lib/thin/connection.rb:84:in `catch'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/thin-1.6.3/lib/thin/connection.rb:84:in `pre_process'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/eventmachine-1.0.8/lib/eventmachine.rb:1062:in `call'\", \"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/eventmachine-1.0.8/lib/eventmachine.rb:1062:in `block in spawn_threadpool'\"]}","log_level":"error","source":"cc.api","data":{"request_guid":"d44f2a12-873f-437f-7d2c-f261f503640f::1d2ea0bc-1a78-49ea-85ff-bfb9c11d2f2b"},"thread_id":47241509083720,"fiber_id":47241507190360,"process_id":5222,"file":"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/lib/sinatra/vcap.rb","lineno":53,"method":"block in registered"}

Any thoughts on what might be causing this? I guess it could be SSL-related or UAA related from the above, however I haven't found anything in any other logs to explain it yet (of course, I could be looking in the wrong place!)

Thanks
James

Join cf-dev@lists.cloudfoundry.org to automatically receive all group messages.