Ask Your Question

Revision history [back]

click to hide/show revision 1
initial version

Unable to launch instance, ClientException

New installation of Kilo, 3 nodes, controller, network, compute. All CentOS 7. Followed the doc, fairly straight forward. This is the first instance I've tried to launch, I have not gotten any instance to successfully launch. Running as admin, and I haven't come across any other erorrs as I try to describe the various resources (image, nic, security group, etc) to try to isolate the problem. I have debugging on in all the components, and can't find any other errors in the other logs. I'm stumped.

[root@bosscrm-os-controller1 nova]# nova  boot --flavor 1 --image 046e1504-27d6-4732-88e5-db2fbee4d95f --nic port-id=d650dfab-3bf9-400f-8526-bc74e250623d  --security-group default --key-name demo-key demo-instance1
ERROR (ClientException): The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-d7d25fa5-e991-46ce-9610-3a6e7db1d396)

With --debug:

[root@bosscrm-os-controller1 nova]# nova --debug  boot --flavor 1 --image 046e1504-27d6-4732-88e5-db2fbee4d95f --nic port-id=d650dfab-3bf9-400f-8526-bc74e250623d  --security-group default --key-name demo-key demo-instance1
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:35357/v3 -H "Accept: application/json" -H "User-Agent: python-keystoneclient"
INFO (connectionpool:203) Starting new HTTP connection (1): bosscrm-os-controller1
DEBUG (connectionpool:383) "GET /v3 HTTP/1.1" 200 262
DEBUG (session:224) RESP: [200] content-length: 262 vary: X-Auth-Token keep-alive: timeout=5, max=100 server: Apache/2.4.6 (CentOS) mod_wsgi/3.4 Python/2.7.5 connection: Keep-Alive date: Thu, 21 May 2015 15:59:17 GMT content-type: application/json x-openstack-request-id: req-02482116-da33-4cd6-b093-b944e51ba95e
RESP BODY: {"version": {"status": "stable", "updated": "2015-03-30T00:00:00Z", "media-types": [{"base": "application/json", "type": "application/vnd.openstack.identity-v3+json"}], "id": "v3.4", "links": [{"href": "http://bosscrm-os-controller1:35357/v3/", "rel": "self"}]}}

DEBUG (base:178) Making authentication request to http://bosscrm-os-controller1:35357/v3/auth/tokens
DEBUG (connectionpool:383) "POST /v3/auth/tokens HTTP/1.1" 201 2946
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d"
INFO (connectionpool:203) Starting new HTTP connection (1): bosscrm-os-controller1
DEBUG (connectionpool:383) "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" 200 725
DEBUG (session:224) RESP: [200] date: Thu, 21 May 2015 15:59:17 GMT connection: keep-alive content-type: application/json content-length: 725 x-compute-request-id: req-1f923b87-03f3-4266-8fa7-f40080d68685
RESP BODY: {"image": {"status": "ACTIVE", "updated": "2015-05-18T17:25:11Z", "links": [{"href": "http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "rel": "self"}, {"href": "http://bosscrm-os-controller1:8774/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "rel": "bookmark"}, {"href": "http://bosscrm-os-controller1:9292/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "type": "application/vnd.openstack.image", "rel": "alternate"}], "id": "046e1504-27d6-4732-88e5-db2fbee4d95f", "OS-EXT-IMG-SIZE:size": 13287936, "name": "cirros-0.3.4-x86_64", "created": "2015-05-18T17:25:11Z", "minDisk": 0, "progress": 100, "minRam": 0, "metadata": {}}}

DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/flavors/1 -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d"
DEBUG (connectionpool:383) "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" 200 442
DEBUG (session:224) RESP: [200] date: Thu, 21 May 2015 15:59:17 GMT connection: keep-alive content-type: application/json content-length: 442 x-compute-request-id: req-06362d15-5eff-44ca-a8d1-33b82bb545f9
RESP BODY: {"flavor": {"name": "m1.tiny", "links": [{"href": "http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/flavors/1", "rel": "self"}, {"href": "http://bosscrm-os-controller1:8774/aaf543afac8143b9a4abd971325de12e/flavors/1", "rel": "bookmark"}], "ram": 512, "OS-FLV-DISABLED:disabled": false, "vcpus": 1, "swap": "", "os-flavor-access:is_public": true, "rxtx_factor": 1.0, "OS-FLV-EXT-DATA:ephemeral": 0, "disk": 1, "id": "1"}}

DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X POST http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers -H "User-Agent: python-novaclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d" -d '{"server": {"name": "demo-instance1", "imageRef": "046e1504-27d6-4732-88e5-db2fbee4d95f", "key_name": "demo-key", "flavorRef": "1", "max_count": 1, "min_count": 1, "networks": [{"port": "d650dfab-3bf9-400f-8526-bc74e250623d"}], "security_groups": [{"name": "default"}]}}'
DEBUG (connectionpool:383) "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" 500 128
DEBUG (session:224) RESP:
DEBUG (shell:819) The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/novaclient/shell.py", line 816, in main
    OpenStackComputeShell().main(argv)
  File "/usr/lib/python2.7/site-packages/novaclient/shell.py", line 743, in main
    args.func(self.cs, args)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/shell.py", line 504, in do_boot
    server = cs.servers.create(*boot_args, **boot_kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/servers.py", line 916, in create
    **boot_kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/servers.py", line 540, in _boot
    return_raw=return_raw, **kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/base.py", line 161, in _create
    _resp, body = self.api.client.post(url, body=body)
  File "/usr/lib/python2.7/site-packages/keystoneclient/adapter.py", line 176, in post
    return self.request(url, 'POST', **kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/client.py", line 104, in request
    raise exceptions.from_response(resp, body, url, method)
ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)
ERROR (ClientException): The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)

In the nova-api.log:

2015-05-21 11:54:12.235 23953 INFO nova.osapi_compute.wsgi.server [req-7c26fbd7-7281-4e9f-9747-c68fa26ae401 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" status:
200 len: 922 time: 0.3420901
2015-05-21 11:54:12.257 23953 INFO nova.osapi_compute.wsgi.server [req-14f7907c-08f4-46e1-be4e-0072dea2c96c 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" status: 200 len: 639 time: 0.0176299
2015-05-21 11:54:12.559 23953 ERROR nova.api.openstack [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] Caught error: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it
is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-03418635-5f4d-46d1-b19c-dc8148f3ffdb)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack Traceback (most recent call last):
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/__init__.py", line 125, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return req.get_response(self.application)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     application, catch_exc_info=False)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 634, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self._call_app(env, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 554, in _call_app
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self._app(env, _fake_start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     response = self.app(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 756, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     content_type, body, accept)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 821, in _process_stack
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 911, in dispatch
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return method(req=request, **action_args)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 636, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     self._handle_create_exception(*sys.exc_info())
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 465, in _handle_create_exception
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     six.reraise(*exc_info)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 621, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 149, in inner
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     rv = f(*args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1481, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1100, in _create_instance
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     auto_disk_config, reservation_id, max_count)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 853, in _validate_and_build_base_options
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     pci_request_info, requested_networks)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 894, in create_pci_requests_for_sriov_ports
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     neutron = get_client(context, admin=True)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 205, in get_client
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     auth_token = _ADMIN_AUTH.get_token(_SESSION)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 105, in get_token
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.get_access(session).auth_token
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 145, in get_access
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     self.auth_ref = self.get_auth_ref(session)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v2.py", line 78, in get_auth_ref
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     authenticated=False, log=False)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 497, in post
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.request(url, 'POST', **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return func(*args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 397, in request
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     raise exceptions.from_response(resp, method, url)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack BadRequest: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-0341863
5-5f4d-46d1-b19c-dc8148f3ffdb)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack
2015-05-21 11:54:12.562 23953 INFO nova.api.openstack [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers returned with HTTP 500
2015-05-21 11:54:12.563 23953 INFO nova.osapi_compute.wsgi.server [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" status: 500 len: 359 time: 0.3005691
2015-05-21 11:54:39.929 23955 INFO nova.osapi_compute.wsgi.server [req-87cf6d0f-659c-48ba-b5b2-8a54976e80de 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" status:
200 len: 922 time: 0.9156430
2015-05-21 11:54:40.149 23955 INFO nova.osapi_compute.wsgi.server [req-f2c4a597-1ba3-4ea4-b240-6dd3e345e030 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" status: 200 len: 639 time: 0.2103288
2015-05-21 11:54:40.450 23955 ERROR nova.api.openstack [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] Caught error: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it
is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-52f5cc08-ebd9-45bf-8031-31f530473460)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack Traceback (most recent call last):
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/__init__.py", line 125, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return req.get_response(self.application)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     application, catch_exc_info=False)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 634, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self._call_app(env, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 554, in _call_app
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self._app(env, _fake_start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     response = self.app(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 756, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     content_type, body, accept)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 821, in _process_stack
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 911, in dispatch
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return method(req=request, **action_args)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 636, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     self._handle_create_exception(*sys.exc_info())
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 465, in _handle_create_exception
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     six.reraise(*exc_info)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 621, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 149, in inner
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     rv = f(*args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1481, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1100, in _create_instance
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     auto_disk_config, reservation_id, max_count)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 853, in _validate_and_build_base_options
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     pci_request_info, requested_networks)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 894, in create_pci_requests_for_sriov_ports
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     neutron = get_client(context, admin=True)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 205, in get_client
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     auth_token = _ADMIN_AUTH.get_token(_SESSION)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 105, in get_token
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.get_access(session).auth_token
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 145, in get_access
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     self.auth_ref = self.get_auth_ref(session)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v2.py", line 78, in get_auth_ref
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     authenticated=False, log=False)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 497, in post
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.request(url, 'POST', **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return func(*args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 397, in request
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     raise exceptions.from_response(resp, method, url)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack BadRequest: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-52f5cc08-ebd9-45bf-8031-31f530473460)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack
2015-05-21 11:54:40.456 23955 INFO nova.api.openstack [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers returned with HTTP 500
2015-05-21 11:54:40.457 23955 INFO nova.osapi_compute.wsgi.server [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" status: 500 len: 359 time: 0.3056350

Unable to launch instance, ClientException

New installation of Kilo, 3 nodes, controller, network, compute. All CentOS 7. Followed the doc, fairly straight forward. This is the first instance I've tried to launch, I have not gotten any instance to successfully launch. Running as admin, and I haven't come across any other erorrs as I try to describe the various resources (image, nic, security group, etc) to try to isolate the problem. I have debugging on in all the components, and can't find any other errors in the other logs. I'm stumped.

[root@bosscrm-os-controller1 nova]# nova  boot --flavor 1 --image 046e1504-27d6-4732-88e5-db2fbee4d95f --nic port-id=d650dfab-3bf9-400f-8526-bc74e250623d  --security-group default --key-name demo-key demo-instance1
ERROR (ClientException): The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-d7d25fa5-e991-46ce-9610-3a6e7db1d396)

With --debug:

[root@bosscrm-os-controller1 nova]# nova --debug  boot --flavor 1 --image 046e1504-27d6-4732-88e5-db2fbee4d95f --nic port-id=d650dfab-3bf9-400f-8526-bc74e250623d  --security-group default --key-name demo-key demo-instance1
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:35357/v3 -H "Accept: application/json" -H "User-Agent: python-keystoneclient"
INFO (connectionpool:203) Starting new HTTP connection (1): bosscrm-os-controller1
DEBUG (connectionpool:383) "GET /v3 HTTP/1.1" 200 262
DEBUG (session:224) RESP: [200] content-length: 262 vary: X-Auth-Token keep-alive: timeout=5, max=100 server: Apache/2.4.6 (CentOS) mod_wsgi/3.4 Python/2.7.5 connection: Keep-Alive date: Thu, 21 May 2015 15:59:17 GMT content-type: application/json x-openstack-request-id: req-02482116-da33-4cd6-b093-b944e51ba95e
RESP BODY: {"version": {"status": "stable", "updated": "2015-03-30T00:00:00Z", "media-types": [{"base": "application/json", "type": "application/vnd.openstack.identity-v3+json"}], "id": "v3.4", "links": [{"href": "http://bosscrm-os-controller1:35357/v3/", "rel": "self"}]}}

DEBUG (base:178) Making authentication request to http://bosscrm-os-controller1:35357/v3/auth/tokens
DEBUG (connectionpool:383) "POST /v3/auth/tokens HTTP/1.1" 201 2946
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d"
INFO (connectionpool:203) Starting new HTTP connection (1): bosscrm-os-controller1
DEBUG (connectionpool:383) "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" 200 725
DEBUG (session:224) RESP: [200] date: Thu, 21 May 2015 15:59:17 GMT connection: keep-alive content-type: application/json content-length: 725 x-compute-request-id: req-1f923b87-03f3-4266-8fa7-f40080d68685
RESP BODY: {"image": {"status": "ACTIVE", "updated": "2015-05-18T17:25:11Z", "links": [{"href": "http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "rel": "self"}, {"href": "http://bosscrm-os-controller1:8774/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "rel": "bookmark"}, {"href": "http://bosscrm-os-controller1:9292/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "type": "application/vnd.openstack.image", "rel": "alternate"}], "id": "046e1504-27d6-4732-88e5-db2fbee4d95f", "OS-EXT-IMG-SIZE:size": 13287936, "name": "cirros-0.3.4-x86_64", "created": "2015-05-18T17:25:11Z", "minDisk": 0, "progress": 100, "minRam": 0, "metadata": {}}}

DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/flavors/1 -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d"
DEBUG (connectionpool:383) "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" 200 442
DEBUG (session:224) RESP: [200] date: Thu, 21 May 2015 15:59:17 GMT connection: keep-alive content-type: application/json content-length: 442 x-compute-request-id: req-06362d15-5eff-44ca-a8d1-33b82bb545f9
RESP BODY: {"flavor": {"name": "m1.tiny", "links": [{"href": "http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/flavors/1", "rel": "self"}, {"href": "http://bosscrm-os-controller1:8774/aaf543afac8143b9a4abd971325de12e/flavors/1", "rel": "bookmark"}], "ram": 512, "OS-FLV-DISABLED:disabled": false, "vcpus": 1, "swap": "", "os-flavor-access:is_public": true, "rxtx_factor": 1.0, "OS-FLV-EXT-DATA:ephemeral": 0, "disk": 1, "id": "1"}}

DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X POST http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers -H "User-Agent: python-novaclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d" -d '{"server": {"name": "demo-instance1", "imageRef": "046e1504-27d6-4732-88e5-db2fbee4d95f", "key_name": "demo-key", "flavorRef": "1", "max_count": 1, "min_count": 1, "networks": [{"port": "d650dfab-3bf9-400f-8526-bc74e250623d"}], "security_groups": [{"name": "default"}]}}'
DEBUG (connectionpool:383) "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" 500 128
DEBUG (session:224) RESP:
DEBUG (shell:819) The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/novaclient/shell.py", line 816, in main
    OpenStackComputeShell().main(argv)
  File "/usr/lib/python2.7/site-packages/novaclient/shell.py", line 743, in main
    args.func(self.cs, args)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/shell.py", line 504, in do_boot
    server = cs.servers.create(*boot_args, **boot_kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/servers.py", line 916, in create
    **boot_kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/servers.py", line 540, in _boot
    return_raw=return_raw, **kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/base.py", line 161, in _create
    _resp, body = self.api.client.post(url, body=body)
  File "/usr/lib/python2.7/site-packages/keystoneclient/adapter.py", line 176, in post
    return self.request(url, 'POST', **kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/client.py", line 104, in request
    raise exceptions.from_response(resp, body, url, method)
ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)
ERROR (ClientException): The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)

In the nova-api.log:

2015-05-21 11:54:12.235 23953 INFO nova.osapi_compute.wsgi.server [req-7c26fbd7-7281-4e9f-9747-c68fa26ae401 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" status:
200 len: 922 time: 0.3420901
2015-05-21 11:54:12.257 23953 INFO nova.osapi_compute.wsgi.server [req-14f7907c-08f4-46e1-be4e-0072dea2c96c 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" status: 200 len: 639 time: 0.0176299
2015-05-21 11:54:12.559 23953 ERROR nova.api.openstack [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] Caught error: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it
is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-03418635-5f4d-46d1-b19c-dc8148f3ffdb)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack Traceback (most recent call last):
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/__init__.py", line 125, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return req.get_response(self.application)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     application, catch_exc_info=False)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 634, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self._call_app(env, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 554, in _call_app
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self._app(env, _fake_start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     response = self.app(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 756, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     content_type, body, accept)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 821, in _process_stack
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 911, in dispatch
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return method(req=request, **action_args)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 636, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     self._handle_create_exception(*sys.exc_info())
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 465, in _handle_create_exception
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     six.reraise(*exc_info)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 621, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 149, in inner
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     rv = f(*args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1481, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1100, in _create_instance
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     auto_disk_config, reservation_id, max_count)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 853, in _validate_and_build_base_options
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     pci_request_info, requested_networks)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 894, in create_pci_requests_for_sriov_ports
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     neutron = get_client(context, admin=True)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 205, in get_client
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     auth_token = _ADMIN_AUTH.get_token(_SESSION)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 105, in get_token
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.get_access(session).auth_token
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 145, in get_access
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     self.auth_ref = self.get_auth_ref(session)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v2.py", line 78, in get_auth_ref
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     authenticated=False, log=False)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 497, in post
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.request(url, 'POST', **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return func(*args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 397, in request
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     raise exceptions.from_response(resp, method, url)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack BadRequest: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-0341863
5-5f4d-46d1-b19c-dc8148f3ffdb)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack
2015-05-21 11:54:12.562 23953 INFO nova.api.openstack [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers returned with HTTP 500
2015-05-21 11:54:12.563 23953 INFO nova.osapi_compute.wsgi.server [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" status: 500 len: 359 time: 0.3005691
2015-05-21 11:54:39.929 23955 INFO nova.osapi_compute.wsgi.server [req-87cf6d0f-659c-48ba-b5b2-8a54976e80de 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" status:
200 len: 922 time: 0.9156430
2015-05-21 11:54:40.149 23955 INFO nova.osapi_compute.wsgi.server [req-f2c4a597-1ba3-4ea4-b240-6dd3e345e030 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" status: 200 len: 639 time: 0.2103288
2015-05-21 11:54:40.450 23955 ERROR nova.api.openstack [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] Caught error: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it
is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-52f5cc08-ebd9-45bf-8031-31f530473460)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack Traceback (most recent call last):
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/__init__.py", line 125, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return req.get_response(self.application)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     application, catch_exc_info=False)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 634, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self._call_app(env, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 554, in _call_app
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self._app(env, _fake_start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     response = self.app(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 756, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     content_type, body, accept)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 821, in _process_stack
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 911, in dispatch
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return method(req=request, **action_args)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 636, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     self._handle_create_exception(*sys.exc_info())
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 465, in _handle_create_exception
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     six.reraise(*exc_info)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 621, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 149, in inner
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     rv = f(*args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1481, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1100, in _create_instance
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     auto_disk_config, reservation_id, max_count)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 853, in _validate_and_build_base_options
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     pci_request_info, requested_networks)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 894, in create_pci_requests_for_sriov_ports
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     neutron = get_client(context, admin=True)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 205, in get_client
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     auth_token = _ADMIN_AUTH.get_token(_SESSION)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 105, in get_token
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.get_access(session).auth_token
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 145, in get_access
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     self.auth_ref = self.get_auth_ref(session)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v2.py", line 78, in get_auth_ref
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     authenticated=False, log=False)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 497, in post
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.request(url, 'POST', **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return func(*args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 397, in request
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     raise exceptions.from_response(resp, method, url)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack BadRequest: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-52f5cc08-ebd9-45bf-8031-31f530473460)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack
2015-05-21 11:54:40.456 23955 INFO nova.api.openstack [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers returned with HTTP 500
2015-05-21 11:54:40.457 23955 INFO nova.osapi_compute.wsgi.server [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" status: 500 len: 359 time: 0.3056350

New Kilo install - Unable to launch instance, ClientExceptionno useful errors found

New installation of Kilo, 3 nodes, controller, network, compute. All CentOS 7. Followed the doc, fairly straight forward. This is the first instance I've tried to launch, I have not gotten any instance to successfully launch. Running as admin, and I haven't come across any other erorrs as I try to describe the various resources (image, nic, security group, etc) to try to isolate the problem. I have debugging on in all the components, and can't find any other errors in the other logs. I'm stumped.

[root@bosscrm-os-controller1 nova]# nova  boot --flavor 1 --image 046e1504-27d6-4732-88e5-db2fbee4d95f --nic port-id=d650dfab-3bf9-400f-8526-bc74e250623d  --security-group default --key-name demo-key demo-instance1
ERROR (ClientException): The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-d7d25fa5-e991-46ce-9610-3a6e7db1d396)

With --debug:

[root@bosscrm-os-controller1 nova]# nova --debug  boot --flavor 1 --image 046e1504-27d6-4732-88e5-db2fbee4d95f --nic port-id=d650dfab-3bf9-400f-8526-bc74e250623d  --security-group default --key-name demo-key demo-instance1
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:35357/v3 -H "Accept: application/json" -H "User-Agent: python-keystoneclient"
INFO (connectionpool:203) Starting new HTTP connection (1): bosscrm-os-controller1
DEBUG (connectionpool:383) "GET /v3 HTTP/1.1" 200 262
DEBUG (session:224) RESP: [200] content-length: 262 vary: X-Auth-Token keep-alive: timeout=5, max=100 server: Apache/2.4.6 (CentOS) mod_wsgi/3.4 Python/2.7.5 connection: Keep-Alive date: Thu, 21 May 2015 15:59:17 GMT content-type: application/json x-openstack-request-id: req-02482116-da33-4cd6-b093-b944e51ba95e
RESP BODY: {"version": {"status": "stable", "updated": "2015-03-30T00:00:00Z", "media-types": [{"base": "application/json", "type": "application/vnd.openstack.identity-v3+json"}], "id": "v3.4", "links": [{"href": "http://bosscrm-os-controller1:35357/v3/", "rel": "self"}]}}

DEBUG (base:178) Making authentication request to http://bosscrm-os-controller1:35357/v3/auth/tokens
DEBUG (connectionpool:383) "POST /v3/auth/tokens HTTP/1.1" 201 2946
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d"
INFO (connectionpool:203) Starting new HTTP connection (1): bosscrm-os-controller1
DEBUG (connectionpool:383) "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" 200 725
DEBUG (session:224) RESP: [200] date: Thu, 21 May 2015 15:59:17 GMT connection: keep-alive content-type: application/json content-length: 725 x-compute-request-id: req-1f923b87-03f3-4266-8fa7-f40080d68685
RESP BODY: {"image": {"status": "ACTIVE", "updated": "2015-05-18T17:25:11Z", "links": [{"href": "http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "rel": "self"}, {"href": "http://bosscrm-os-controller1:8774/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "rel": "bookmark"}, {"href": "http://bosscrm-os-controller1:9292/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "type": "application/vnd.openstack.image", "rel": "alternate"}], "id": "046e1504-27d6-4732-88e5-db2fbee4d95f", "OS-EXT-IMG-SIZE:size": 13287936, "name": "cirros-0.3.4-x86_64", "created": "2015-05-18T17:25:11Z", "minDisk": 0, "progress": 100, "minRam": 0, "metadata": {}}}

DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/flavors/1 -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d"
DEBUG (connectionpool:383) "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" 200 442
DEBUG (session:224) RESP: [200] date: Thu, 21 May 2015 15:59:17 GMT connection: keep-alive content-type: application/json content-length: 442 x-compute-request-id: req-06362d15-5eff-44ca-a8d1-33b82bb545f9
RESP BODY: {"flavor": {"name": "m1.tiny", "links": [{"href": "http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/flavors/1", "rel": "self"}, {"href": "http://bosscrm-os-controller1:8774/aaf543afac8143b9a4abd971325de12e/flavors/1", "rel": "bookmark"}], "ram": 512, "OS-FLV-DISABLED:disabled": false, "vcpus": 1, "swap": "", "os-flavor-access:is_public": true, "rxtx_factor": 1.0, "OS-FLV-EXT-DATA:ephemeral": 0, "disk": 1, "id": "1"}}

DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X POST http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers -H "User-Agent: python-novaclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d" -d '{"server": {"name": "demo-instance1", "imageRef": "046e1504-27d6-4732-88e5-db2fbee4d95f", "key_name": "demo-key", "flavorRef": "1", "max_count": 1, "min_count": 1, "networks": [{"port": "d650dfab-3bf9-400f-8526-bc74e250623d"}], "security_groups": [{"name": "default"}]}}'
DEBUG (connectionpool:383) "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" 500 128
DEBUG (session:224) RESP:
DEBUG (shell:819) The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/novaclient/shell.py", line 816, in main
    OpenStackComputeShell().main(argv)
  File "/usr/lib/python2.7/site-packages/novaclient/shell.py", line 743, in main
    args.func(self.cs, args)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/shell.py", line 504, in do_boot
    server = cs.servers.create(*boot_args, **boot_kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/servers.py", line 916, in create
    **boot_kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/servers.py", line 540, in _boot
    return_raw=return_raw, **kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/base.py", line 161, in _create
    _resp, body = self.api.client.post(url, body=body)
  File "/usr/lib/python2.7/site-packages/keystoneclient/adapter.py", line 176, in post
    return self.request(url, 'POST', **kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/client.py", line 104, in request
    raise exceptions.from_response(resp, body, url, method)
ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)
ERROR (ClientException): The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)

In the nova-api.log:

2015-05-21 11:54:12.235 23953 INFO nova.osapi_compute.wsgi.server [req-7c26fbd7-7281-4e9f-9747-c68fa26ae401 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" status:
200 len: 922 time: 0.3420901
2015-05-21 11:54:12.257 23953 INFO nova.osapi_compute.wsgi.server [req-14f7907c-08f4-46e1-be4e-0072dea2c96c 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" status: 200 len: 639 time: 0.0176299
2015-05-21 11:54:12.559 23953 ERROR nova.api.openstack [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] Caught error: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it
is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-03418635-5f4d-46d1-b19c-dc8148f3ffdb)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack Traceback (most recent call last):
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/__init__.py", line 125, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return req.get_response(self.application)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     application, catch_exc_info=False)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 634, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self._call_app(env, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 554, in _call_app
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self._app(env, _fake_start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     response = self.app(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 756, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     content_type, body, accept)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 821, in _process_stack
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 911, in dispatch
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return method(req=request, **action_args)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 636, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     self._handle_create_exception(*sys.exc_info())
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 465, in _handle_create_exception
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     six.reraise(*exc_info)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 621, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 149, in inner
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     rv = f(*args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1481, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1100, in _create_instance
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     auto_disk_config, reservation_id, max_count)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 853, in _validate_and_build_base_options
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     pci_request_info, requested_networks)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 894, in create_pci_requests_for_sriov_ports
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     neutron = get_client(context, admin=True)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 205, in get_client
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     auth_token = _ADMIN_AUTH.get_token(_SESSION)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 105, in get_token
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.get_access(session).auth_token
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 145, in get_access
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     self.auth_ref = self.get_auth_ref(session)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v2.py", line 78, in get_auth_ref
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     authenticated=False, log=False)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 497, in post
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.request(url, 'POST', **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return func(*args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 397, in request
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     raise exceptions.from_response(resp, method, url)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack BadRequest: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-0341863
5-5f4d-46d1-b19c-dc8148f3ffdb)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack
2015-05-21 11:54:12.562 23953 INFO nova.api.openstack [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers returned with HTTP 500
2015-05-21 11:54:12.563 23953 INFO nova.osapi_compute.wsgi.server [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" status: 500 len: 359 time: 0.3005691
2015-05-21 11:54:39.929 23955 INFO nova.osapi_compute.wsgi.server [req-87cf6d0f-659c-48ba-b5b2-8a54976e80de 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" status:
200 len: 922 time: 0.9156430
2015-05-21 11:54:40.149 23955 INFO nova.osapi_compute.wsgi.server [req-f2c4a597-1ba3-4ea4-b240-6dd3e345e030 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" status: 200 len: 639 time: 0.2103288
2015-05-21 11:54:40.450 23955 ERROR nova.api.openstack [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] Caught error: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it
is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-52f5cc08-ebd9-45bf-8031-31f530473460)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack Traceback (most recent call last):
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/__init__.py", line 125, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return req.get_response(self.application)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     application, catch_exc_info=False)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 634, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self._call_app(env, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 554, in _call_app
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self._app(env, _fake_start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     response = self.app(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 756, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     content_type, body, accept)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 821, in _process_stack
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 911, in dispatch
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return method(req=request, **action_args)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 636, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     self._handle_create_exception(*sys.exc_info())
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 465, in _handle_create_exception
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     six.reraise(*exc_info)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 621, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 149, in inner
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     rv = f(*args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1481, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1100, in _create_instance
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     auto_disk_config, reservation_id, max_count)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 853, in _validate_and_build_base_options
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     pci_request_info, requested_networks)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 894, in create_pci_requests_for_sriov_ports
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     neutron = get_client(context, admin=True)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 205, in get_client
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     auth_token = _ADMIN_AUTH.get_token(_SESSION)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 105, in get_token
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.get_access(session).auth_token
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 145, in get_access
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     self.auth_ref = self.get_auth_ref(session)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v2.py", line 78, in get_auth_ref
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     authenticated=False, log=False)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 497, in post
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.request(url, 'POST', **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return func(*args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 397, in request
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     raise exceptions.from_response(resp, method, url)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack BadRequest: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-52f5cc08-ebd9-45bf-8031-31f530473460)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack
2015-05-21 11:54:40.456 23955 INFO nova.api.openstack [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers returned with HTTP 500
2015-05-21 11:54:40.457 23955 INFO nova.osapi_compute.wsgi.server [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" status: 500 len: 359 time: 0.3056350

New Kilo install - Unable to launch instance, no useful errors found

New installation of Kilo, 3 nodes, controller, network, compute. All CentOS 7. Followed the doc, fairly straight forward. This is the first instance I've tried to launch, I have not gotten any instance to successfully launch. Running as admin, and I haven't come across any other erorrs as I try to describe the various resources (image, nic, security group, etc) to try to isolate the problem. I have debugging on in all the components, and can't find any other errors in the other logs. I'm stumped.

edit - I see the same error as majiclamp when doing 'nova endpoints'. I get a list of endpoints for each service, one for each interface (internal, admin,public), all in RegionOne, but at the start of each service (glance, neutron,keystone, nova), I get

WARNING: nova has no endpoint in ! Available endpoints for this service:

Also - I can do an 'openstack token issue' using the admin account, and the nova account, when the username and password is provided in the environment variables, but not when provided as command line arguments.

-end edit

[root@bosscrm-os-controller1 nova]# nova  boot --flavor 1 --image 046e1504-27d6-4732-88e5-db2fbee4d95f --nic port-id=d650dfab-3bf9-400f-8526-bc74e250623d  --security-group default --key-name demo-key demo-instance1
ERROR (ClientException): The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-d7d25fa5-e991-46ce-9610-3a6e7db1d396)

With --debug:

[root@bosscrm-os-controller1 nova]# nova --debug  boot --flavor 1 --image 046e1504-27d6-4732-88e5-db2fbee4d95f --nic port-id=d650dfab-3bf9-400f-8526-bc74e250623d  --security-group default --key-name demo-key demo-instance1
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:35357/v3 -H "Accept: application/json" -H "User-Agent: python-keystoneclient"
INFO (connectionpool:203) Starting new HTTP connection (1): bosscrm-os-controller1
DEBUG (connectionpool:383) "GET /v3 HTTP/1.1" 200 262
DEBUG (session:224) RESP: [200] content-length: 262 vary: X-Auth-Token keep-alive: timeout=5, max=100 server: Apache/2.4.6 (CentOS) mod_wsgi/3.4 Python/2.7.5 connection: Keep-Alive date: Thu, 21 May 2015 15:59:17 GMT content-type: application/json x-openstack-request-id: req-02482116-da33-4cd6-b093-b944e51ba95e
RESP BODY: {"version": {"status": "stable", "updated": "2015-03-30T00:00:00Z", "media-types": [{"base": "application/json", "type": "application/vnd.openstack.identity-v3+json"}], "id": "v3.4", "links": [{"href": "http://bosscrm-os-controller1:35357/v3/", "rel": "self"}]}}

DEBUG (base:178) Making authentication request to http://bosscrm-os-controller1:35357/v3/auth/tokens
DEBUG (connectionpool:383) "POST /v3/auth/tokens HTTP/1.1" 201 2946
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d"
INFO (connectionpool:203) Starting new HTTP connection (1): bosscrm-os-controller1
DEBUG (connectionpool:383) "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" 200 725
DEBUG (session:224) RESP: [200] date: Thu, 21 May 2015 15:59:17 GMT connection: keep-alive content-type: application/json content-length: 725 x-compute-request-id: req-1f923b87-03f3-4266-8fa7-f40080d68685
RESP BODY: {"image": {"status": "ACTIVE", "updated": "2015-05-18T17:25:11Z", "links": [{"href": "http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "rel": "self"}, {"href": "http://bosscrm-os-controller1:8774/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "rel": "bookmark"}, {"href": "http://bosscrm-os-controller1:9292/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "type": "application/vnd.openstack.image", "rel": "alternate"}], "id": "046e1504-27d6-4732-88e5-db2fbee4d95f", "OS-EXT-IMG-SIZE:size": 13287936, "name": "cirros-0.3.4-x86_64", "created": "2015-05-18T17:25:11Z", "minDisk": 0, "progress": 100, "minRam": 0, "metadata": {}}}

DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/flavors/1 -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d"
DEBUG (connectionpool:383) "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" 200 442
DEBUG (session:224) RESP: [200] date: Thu, 21 May 2015 15:59:17 GMT connection: keep-alive content-type: application/json content-length: 442 x-compute-request-id: req-06362d15-5eff-44ca-a8d1-33b82bb545f9
RESP BODY: {"flavor": {"name": "m1.tiny", "links": [{"href": "http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/flavors/1", "rel": "self"}, {"href": "http://bosscrm-os-controller1:8774/aaf543afac8143b9a4abd971325de12e/flavors/1", "rel": "bookmark"}], "ram": 512, "OS-FLV-DISABLED:disabled": false, "vcpus": 1, "swap": "", "os-flavor-access:is_public": true, "rxtx_factor": 1.0, "OS-FLV-EXT-DATA:ephemeral": 0, "disk": 1, "id": "1"}}

DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X POST http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers -H "User-Agent: python-novaclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d" -d '{"server": {"name": "demo-instance1", "imageRef": "046e1504-27d6-4732-88e5-db2fbee4d95f", "key_name": "demo-key", "flavorRef": "1", "max_count": 1, "min_count": 1, "networks": [{"port": "d650dfab-3bf9-400f-8526-bc74e250623d"}], "security_groups": [{"name": "default"}]}}'
DEBUG (connectionpool:383) "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" 500 128
DEBUG (session:224) RESP:
DEBUG (shell:819) The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/novaclient/shell.py", line 816, in main
    OpenStackComputeShell().main(argv)
  File "/usr/lib/python2.7/site-packages/novaclient/shell.py", line 743, in main
    args.func(self.cs, args)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/shell.py", line 504, in do_boot
    server = cs.servers.create(*boot_args, **boot_kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/servers.py", line 916, in create
    **boot_kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/servers.py", line 540, in _boot
    return_raw=return_raw, **kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/base.py", line 161, in _create
    _resp, body = self.api.client.post(url, body=body)
  File "/usr/lib/python2.7/site-packages/keystoneclient/adapter.py", line 176, in post
    return self.request(url, 'POST', **kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/client.py", line 104, in request
    raise exceptions.from_response(resp, body, url, method)
ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)
ERROR (ClientException): The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)

In the nova-api.log:

2015-05-21 11:54:12.235 23953 INFO nova.osapi_compute.wsgi.server [req-7c26fbd7-7281-4e9f-9747-c68fa26ae401 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" status:
200 len: 922 time: 0.3420901
2015-05-21 11:54:12.257 23953 INFO nova.osapi_compute.wsgi.server [req-14f7907c-08f4-46e1-be4e-0072dea2c96c 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" status: 200 len: 639 time: 0.0176299
2015-05-21 11:54:12.559 23953 ERROR nova.api.openstack [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] Caught error: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it
is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-03418635-5f4d-46d1-b19c-dc8148f3ffdb)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack Traceback (most recent call last):
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/__init__.py", line 125, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return req.get_response(self.application)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     application, catch_exc_info=False)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 634, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self._call_app(env, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 554, in _call_app
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self._app(env, _fake_start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     response = self.app(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 756, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     content_type, body, accept)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 821, in _process_stack
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 911, in dispatch
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return method(req=request, **action_args)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 636, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     self._handle_create_exception(*sys.exc_info())
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 465, in _handle_create_exception
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     six.reraise(*exc_info)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 621, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 149, in inner
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     rv = f(*args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1481, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1100, in _create_instance
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     auto_disk_config, reservation_id, max_count)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 853, in _validate_and_build_base_options
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     pci_request_info, requested_networks)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 894, in create_pci_requests_for_sriov_ports
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     neutron = get_client(context, admin=True)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 205, in get_client
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     auth_token = _ADMIN_AUTH.get_token(_SESSION)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 105, in get_token
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.get_access(session).auth_token
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 145, in get_access
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     self.auth_ref = self.get_auth_ref(session)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v2.py", line 78, in get_auth_ref
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     authenticated=False, log=False)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 497, in post
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.request(url, 'POST', **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return func(*args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 397, in request
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     raise exceptions.from_response(resp, method, url)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack BadRequest: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-0341863
5-5f4d-46d1-b19c-dc8148f3ffdb)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack
2015-05-21 11:54:12.562 23953 INFO nova.api.openstack [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers returned with HTTP 500
2015-05-21 11:54:12.563 23953 INFO nova.osapi_compute.wsgi.server [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" status: 500 len: 359 time: 0.3005691
2015-05-21 11:54:39.929 23955 INFO nova.osapi_compute.wsgi.server [req-87cf6d0f-659c-48ba-b5b2-8a54976e80de 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" status:
200 len: 922 time: 0.9156430
2015-05-21 11:54:40.149 23955 INFO nova.osapi_compute.wsgi.server [req-f2c4a597-1ba3-4ea4-b240-6dd3e345e030 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" status: 200 len: 639 time: 0.2103288
2015-05-21 11:54:40.450 23955 ERROR nova.api.openstack [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] Caught error: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it
is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-52f5cc08-ebd9-45bf-8031-31f530473460)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack Traceback (most recent call last):
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/__init__.py", line 125, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return req.get_response(self.application)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     application, catch_exc_info=False)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 634, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self._call_app(env, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 554, in _call_app
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self._app(env, _fake_start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     response = self.app(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 756, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     content_type, body, accept)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 821, in _process_stack
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 911, in dispatch
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return method(req=request, **action_args)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 636, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     self._handle_create_exception(*sys.exc_info())
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 465, in _handle_create_exception
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     six.reraise(*exc_info)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 621, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 149, in inner
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     rv = f(*args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1481, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1100, in _create_instance
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     auto_disk_config, reservation_id, max_count)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 853, in _validate_and_build_base_options
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     pci_request_info, requested_networks)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 894, in create_pci_requests_for_sriov_ports
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     neutron = get_client(context, admin=True)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 205, in get_client
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     auth_token = _ADMIN_AUTH.get_token(_SESSION)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 105, in get_token
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.get_access(session).auth_token
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 145, in get_access
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     self.auth_ref = self.get_auth_ref(session)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v2.py", line 78, in get_auth_ref
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     authenticated=False, log=False)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 497, in post
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.request(url, 'POST', **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return func(*args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 397, in request
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     raise exceptions.from_response(resp, method, url)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack BadRequest: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-52f5cc08-ebd9-45bf-8031-31f530473460)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack
2015-05-21 11:54:40.456 23955 INFO nova.api.openstack [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers returned with HTTP 500
2015-05-21 11:54:40.457 23955 INFO nova.osapi_compute.wsgi.server [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" status: 500 len: 359 time: 0.3056350

New Kilo install - Unable to launch instance, no useful errors found

New installation of Kilo, 3 nodes, controller, network, compute. All CentOS 7. Followed the doc, fairly straight forward. This is the first instance I've tried to launch, I have not gotten any instance to successfully launch. Running as admin, and I haven't come across any other erorrs as I try to describe the various resources (image, nic, security group, etc) to try to isolate the problem. I have debugging on in all the components, and can't find any other errors in the other logs. I'm stumped.

edit - I see the same error as majiclamp when doing 'nova endpoints'. I get a list of endpoints for each service, one for each interface (internal, admin,public), all in RegionOne, but at the start of each service (glance, neutron,keystone, nova), I get

WARNING: nova has no endpoint in ! Available endpoints for this service:

Also - I can do an 'openstack token issue' using the admin account, and the nova account, when the username and password is provided in the environment variables, but not when provided as command line arguments.

-end edit

[root@bosscrm-os-controller1 nova]# nova  boot --flavor 1 --image 046e1504-27d6-4732-88e5-db2fbee4d95f --nic port-id=d650dfab-3bf9-400f-8526-bc74e250623d  --security-group default --key-name demo-key demo-instance1
ERROR (ClientException): The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-d7d25fa5-e991-46ce-9610-3a6e7db1d396)

With --debug:

[root@bosscrm-os-controller1 nova]# nova --debug  boot --flavor 1 --image 046e1504-27d6-4732-88e5-db2fbee4d95f --nic port-id=d650dfab-3bf9-400f-8526-bc74e250623d  --security-group default --key-name demo-key demo-instance1
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:35357/v3 -H "Accept: application/json" -H "User-Agent: python-keystoneclient"
INFO (connectionpool:203) Starting new HTTP connection (1): bosscrm-os-controller1
DEBUG (connectionpool:383) "GET /v3 HTTP/1.1" 200 262
DEBUG (session:224) RESP: [200] content-length: 262 vary: X-Auth-Token keep-alive: timeout=5, max=100 server: Apache/2.4.6 (CentOS) mod_wsgi/3.4 Python/2.7.5 connection: Keep-Alive date: Thu, 21 May 2015 15:59:17 GMT content-type: application/json x-openstack-request-id: req-02482116-da33-4cd6-b093-b944e51ba95e
RESP BODY: {"version": {"status": "stable", "updated": "2015-03-30T00:00:00Z", "media-types": [{"base": "application/json", "type": "application/vnd.openstack.identity-v3+json"}], "id": "v3.4", "links": [{"href": "http://bosscrm-os-controller1:35357/v3/", "rel": "self"}]}}

DEBUG (base:178) Making authentication request to http://bosscrm-os-controller1:35357/v3/auth/tokens
DEBUG (connectionpool:383) "POST /v3/auth/tokens HTTP/1.1" 201 2946
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d"
INFO (connectionpool:203) Starting new HTTP connection (1): bosscrm-os-controller1
DEBUG (connectionpool:383) "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" 200 725
DEBUG (session:224) RESP: [200] date: Thu, 21 May 2015 15:59:17 GMT connection: keep-alive content-type: application/json content-length: 725 x-compute-request-id: req-1f923b87-03f3-4266-8fa7-f40080d68685
RESP BODY: {"image": {"status": "ACTIVE", "updated": "2015-05-18T17:25:11Z", "links": [{"href": "http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "rel": "self"}, {"href": "http://bosscrm-os-controller1:8774/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "rel": "bookmark"}, {"href": "http://bosscrm-os-controller1:9292/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "type": "application/vnd.openstack.image", "rel": "alternate"}], "id": "046e1504-27d6-4732-88e5-db2fbee4d95f", "OS-EXT-IMG-SIZE:size": 13287936, "name": "cirros-0.3.4-x86_64", "created": "2015-05-18T17:25:11Z", "minDisk": 0, "progress": 100, "minRam": 0, "metadata": {}}}

DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/flavors/1 -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d"
DEBUG (connectionpool:383) "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" 200 442
DEBUG (session:224) RESP: [200] date: Thu, 21 May 2015 15:59:17 GMT connection: keep-alive content-type: application/json content-length: 442 x-compute-request-id: req-06362d15-5eff-44ca-a8d1-33b82bb545f9
RESP BODY: {"flavor": {"name": "m1.tiny", "links": [{"href": "http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/flavors/1", "rel": "self"}, {"href": "http://bosscrm-os-controller1:8774/aaf543afac8143b9a4abd971325de12e/flavors/1", "rel": "bookmark"}], "ram": 512, "OS-FLV-DISABLED:disabled": false, "vcpus": 1, "swap": "", "os-flavor-access:is_public": true, "rxtx_factor": 1.0, "OS-FLV-EXT-DATA:ephemeral": 0, "disk": 1, "id": "1"}}

DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X POST http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers -H "User-Agent: python-novaclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d" -d '{"server": {"name": "demo-instance1", "imageRef": "046e1504-27d6-4732-88e5-db2fbee4d95f", "key_name": "demo-key", "flavorRef": "1", "max_count": 1, "min_count": 1, "networks": [{"port": "d650dfab-3bf9-400f-8526-bc74e250623d"}], "security_groups": [{"name": "default"}]}}'
DEBUG (connectionpool:383) "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" 500 128
DEBUG (session:224) RESP:
DEBUG (shell:819) The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/novaclient/shell.py", line 816, in main
    OpenStackComputeShell().main(argv)
  File "/usr/lib/python2.7/site-packages/novaclient/shell.py", line 743, in main
    args.func(self.cs, args)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/shell.py", line 504, in do_boot
    server = cs.servers.create(*boot_args, **boot_kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/servers.py", line 916, in create
    **boot_kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/servers.py", line 540, in _boot
    return_raw=return_raw, **kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/base.py", line 161, in _create
    _resp, body = self.api.client.post(url, body=body)
  File "/usr/lib/python2.7/site-packages/keystoneclient/adapter.py", line 176, in post
    return self.request(url, 'POST', **kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/client.py", line 104, in request
    raise exceptions.from_response(resp, body, url, method)
ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)
ERROR (ClientException): The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)

In the nova-api.log:

2015-05-21 11:54:12.235 23953 INFO nova.osapi_compute.wsgi.server [req-7c26fbd7-7281-4e9f-9747-c68fa26ae401 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" status:
200 len: 922 time: 0.3420901
2015-05-21 11:54:12.257 23953 INFO nova.osapi_compute.wsgi.server [req-14f7907c-08f4-46e1-be4e-0072dea2c96c 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" status: 200 len: 639 time: 0.0176299
2015-05-21 11:54:12.559 23953 ERROR nova.api.openstack [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] Caught error: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it
is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-03418635-5f4d-46d1-b19c-dc8148f3ffdb)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack Traceback (most recent call last):
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/__init__.py", line 125, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return req.get_response(self.application)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     application, catch_exc_info=False)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 634, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self._call_app(env, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 554, in _call_app
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self._app(env, _fake_start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     response = self.app(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 756, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     content_type, body, accept)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 821, in _process_stack
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 911, in dispatch
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return method(req=request, **action_args)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 636, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     self._handle_create_exception(*sys.exc_info())
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 465, in _handle_create_exception
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     six.reraise(*exc_info)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 621, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 149, in inner
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     rv = f(*args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1481, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1100, in _create_instance
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     auto_disk_config, reservation_id, max_count)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 853, in _validate_and_build_base_options
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     pci_request_info, requested_networks)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 894, in create_pci_requests_for_sriov_ports
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     neutron = get_client(context, admin=True)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 205, in get_client
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     auth_token = _ADMIN_AUTH.get_token(_SESSION)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 105, in get_token
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.get_access(session).auth_token
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 145, in get_access
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     self.auth_ref = self.get_auth_ref(session)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v2.py", line 78, in get_auth_ref
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     authenticated=False, log=False)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 497, in post
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.request(url, 'POST', **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return func(*args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 397, in request
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     raise exceptions.from_response(resp, method, url)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack BadRequest: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-0341863
5-5f4d-46d1-b19c-dc8148f3ffdb)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack
2015-05-21 11:54:12.562 23953 INFO nova.api.openstack [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers returned with HTTP 500
2015-05-21 11:54:12.563 23953 INFO nova.osapi_compute.wsgi.server [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" status: 500 len: 359 time: 0.3005691
2015-05-21 11:54:39.929 23955 INFO nova.osapi_compute.wsgi.server [req-87cf6d0f-659c-48ba-b5b2-8a54976e80de 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" status:
200 len: 922 time: 0.9156430
2015-05-21 11:54:40.149 23955 INFO nova.osapi_compute.wsgi.server [req-f2c4a597-1ba3-4ea4-b240-6dd3e345e030 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" status: 200 len: 639 time: 0.2103288
2015-05-21 11:54:40.450 23955 ERROR nova.api.openstack [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] Caught error: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it
is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-52f5cc08-ebd9-45bf-8031-31f530473460)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack Traceback (most recent call last):
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/__init__.py", line 125, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return req.get_response(self.application)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     application, catch_exc_info=False)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 634, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self._call_app(env, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 554, in _call_app
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self._app(env, _fake_start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     response = self.app(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 756, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     content_type, body, accept)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 821, in _process_stack
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 911, in dispatch
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return method(req=request, **action_args)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 636, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     self._handle_create_exception(*sys.exc_info())
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 465, in _handle_create_exception
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     six.reraise(*exc_info)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 621, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 149, in inner
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     rv = f(*args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1481, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1100, in _create_instance
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     auto_disk_config, reservation_id, max_count)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 853, in _validate_and_build_base_options
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     pci_request_info, requested_networks)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 894, in create_pci_requests_for_sriov_ports
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     neutron = get_client(context, admin=True)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 205, in get_client
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     auth_token = _ADMIN_AUTH.get_token(_SESSION)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 105, in get_token
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.get_access(session).auth_token
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 145, in get_access
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     self.auth_ref = self.get_auth_ref(session)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v2.py", line 78, in get_auth_ref
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     authenticated=False, log=False)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 497, in post
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.request(url, 'POST', **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return func(*args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 397, in request
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     raise exceptions.from_response(resp, method, url)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack BadRequest: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-52f5cc08-ebd9-45bf-8031-31f530473460)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack
2015-05-21 11:54:40.456 23955 INFO nova.api.openstack [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers returned with HTTP 500
2015-05-21 11:54:40.457 23955 INFO nova.osapi_compute.wsgi.server [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" status: 500 len: 359 time: 0.3056350

New Kilo install - Unable to launch instance, no useful errors found

New installation of Kilo, 3 nodes, controller, network, compute. All CentOS 7. Followed the doc, fairly straight forward. This is the first instance I've tried to launch, I have not gotten any instance to successfully launch. Running as admin, and I haven't come across any other erorrs as I try to describe the various resources (image, nic, security group, etc) to try to isolate the problem. I have debugging on in all the components, and can't find any other errors in the other logs. I'm stumped.

edit - I see the same error as majiclamp when doing 'nova endpoints'. I get a list of endpoints for each service, one for each interface (internal, admin,public), all in RegionOne, but at the start of each service (glance, neutron,keystone, nova), I get

WARNING: nova has no endpoint in ! Available endpoints for this service:

-end edit

[root@bosscrm-os-controller1 nova]# nova  boot --flavor 1 --image 046e1504-27d6-4732-88e5-db2fbee4d95f --nic port-id=d650dfab-3bf9-400f-8526-bc74e250623d  --security-group default --key-name demo-key demo-instance1
ERROR (ClientException): The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-d7d25fa5-e991-46ce-9610-3a6e7db1d396)

With --debug:

[root@bosscrm-os-controller1 nova]# nova --debug  boot --flavor 1 --image 046e1504-27d6-4732-88e5-db2fbee4d95f --nic port-id=d650dfab-3bf9-400f-8526-bc74e250623d  --security-group default --key-name demo-key demo-instance1
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:35357/v3 -H "Accept: application/json" -H "User-Agent: python-keystoneclient"
INFO (connectionpool:203) Starting new HTTP connection (1): bosscrm-os-controller1
DEBUG (connectionpool:383) "GET /v3 HTTP/1.1" 200 262
DEBUG (session:224) RESP: [200] content-length: 262 vary: X-Auth-Token keep-alive: timeout=5, max=100 server: Apache/2.4.6 (CentOS) mod_wsgi/3.4 Python/2.7.5 connection: Keep-Alive date: Thu, 21 May 2015 15:59:17 GMT content-type: application/json x-openstack-request-id: req-02482116-da33-4cd6-b093-b944e51ba95e
RESP BODY: {"version": {"status": "stable", "updated": "2015-03-30T00:00:00Z", "media-types": [{"base": "application/json", "type": "application/vnd.openstack.identity-v3+json"}], "id": "v3.4", "links": [{"href": "http://bosscrm-os-controller1:35357/v3/", "rel": "self"}]}}

DEBUG (base:178) Making authentication request to http://bosscrm-os-controller1:35357/v3/auth/tokens
DEBUG (connectionpool:383) "POST /v3/auth/tokens HTTP/1.1" 201 2946
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d"
INFO (connectionpool:203) Starting new HTTP connection (1): bosscrm-os-controller1
DEBUG (connectionpool:383) "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" 200 725
DEBUG (session:224) RESP: [200] date: Thu, 21 May 2015 15:59:17 GMT connection: keep-alive content-type: application/json content-length: 725 x-compute-request-id: req-1f923b87-03f3-4266-8fa7-f40080d68685
RESP BODY: {"image": {"status": "ACTIVE", "updated": "2015-05-18T17:25:11Z", "links": [{"href": "http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "rel": "self"}, {"href": "http://bosscrm-os-controller1:8774/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "rel": "bookmark"}, {"href": "http://bosscrm-os-controller1:9292/images/046e1504-27d6-4732-88e5-db2fbee4d95f", "type": "application/vnd.openstack.image", "rel": "alternate"}], "id": "046e1504-27d6-4732-88e5-db2fbee4d95f", "OS-EXT-IMG-SIZE:size": 13287936, "name": "cirros-0.3.4-x86_64", "created": "2015-05-18T17:25:11Z", "minDisk": 0, "progress": 100, "minRam": 0, "metadata": {}}}

DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X GET http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/flavors/1 -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d"
DEBUG (connectionpool:383) "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" 200 442
DEBUG (session:224) RESP: [200] date: Thu, 21 May 2015 15:59:17 GMT connection: keep-alive content-type: application/json content-length: 442 x-compute-request-id: req-06362d15-5eff-44ca-a8d1-33b82bb545f9
RESP BODY: {"flavor": {"name": "m1.tiny", "links": [{"href": "http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/flavors/1", "rel": "self"}, {"href": "http://bosscrm-os-controller1:8774/aaf543afac8143b9a4abd971325de12e/flavors/1", "rel": "bookmark"}], "ram": 512, "OS-FLV-DISABLED:disabled": false, "vcpus": 1, "swap": "", "os-flavor-access:is_public": true, "rxtx_factor": 1.0, "OS-FLV-EXT-DATA:ephemeral": 0, "disk": 1, "id": "1"}}

DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (iso8601:184) Parsed 2015-05-21T16:59:17.293613Z into {'tz_sign': None, 'second_fraction': u'293613', 'hour': u'16', 'daydash': u'21', 'tz_hour': None, 'month': None, 'timezone': u'Z', 'second': u'17', 'tz_minute': None, 'year': u'2015', 'separator': u'T', 'monthdash': u'05', 'day': None, 'minute': u'59'} with default timezone <iso8601.iso8601.utc object="" at="" 0x27f0050="">
DEBUG (iso8601:140) Got u'2015' for 'year' with default None
DEBUG (iso8601:140) Got u'05' for 'monthdash' with default 1
DEBUG (iso8601:140) Got 5 for 'month' with default 5
DEBUG (iso8601:140) Got u'21' for 'daydash' with default 1
DEBUG (iso8601:140) Got 21 for 'day' with default 21
DEBUG (iso8601:140) Got u'16' for 'hour' with default None
DEBUG (iso8601:140) Got u'59' for 'minute' with default None
DEBUG (iso8601:140) Got u'17' for 'second' with default None
DEBUG (session:195) REQ: curl -g -i -X POST http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers -H "User-Agent: python-novaclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}691cf7200dab935573c7b1cb54de7551f76d299d" -d '{"server": {"name": "demo-instance1", "imageRef": "046e1504-27d6-4732-88e5-db2fbee4d95f", "key_name": "demo-key", "flavorRef": "1", "max_count": 1, "min_count": 1, "networks": [{"port": "d650dfab-3bf9-400f-8526-bc74e250623d"}], "security_groups": [{"name": "default"}]}}'
DEBUG (connectionpool:383) "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" 500 128
DEBUG (session:224) RESP:
DEBUG (shell:819) The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/novaclient/shell.py", line 816, in main
    OpenStackComputeShell().main(argv)
  File "/usr/lib/python2.7/site-packages/novaclient/shell.py", line 743, in main
    args.func(self.cs, args)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/shell.py", line 504, in do_boot
    server = cs.servers.create(*boot_args, **boot_kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/servers.py", line 916, in create
    **boot_kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/servers.py", line 540, in _boot
    return_raw=return_raw, **kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/base.py", line 161, in _create
    _resp, body = self.api.client.post(url, body=body)
  File "/usr/lib/python2.7/site-packages/keystoneclient/adapter.py", line 176, in post
    return self.request(url, 'POST', **kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/client.py", line 104, in request
    raise exceptions.from_response(resp, body, url, method)
ClientException: The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)
ERROR (ClientException): The server has either erred or is incapable of performing the requested operation. (HTTP 500) (Request-ID: req-46145050-4293-4587-a39f-40fd9bd2a2a0)

In the nova-api.log:

2015-05-21 11:54:12.235 23953 INFO nova.osapi_compute.wsgi.server [req-7c26fbd7-7281-4e9f-9747-c68fa26ae401 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" status:
200 len: 922 time: 0.3420901
2015-05-21 11:54:12.257 23953 INFO nova.osapi_compute.wsgi.server [req-14f7907c-08f4-46e1-be4e-0072dea2c96c 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" status: 200 len: 639 time: 0.0176299
2015-05-21 11:54:12.559 23953 ERROR nova.api.openstack [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] Caught error: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it
is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-03418635-5f4d-46d1-b19c-dc8148f3ffdb)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack Traceback (most recent call last):
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/__init__.py", line 125, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return req.get_response(self.application)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     application, catch_exc_info=False)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 634, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self._call_app(env, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 554, in _call_app
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self._app(env, _fake_start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     response = self.app(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 756, in __call__
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     content_type, body, accept)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 821, in _process_stack
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 911, in dispatch
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return method(req=request, **action_args)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 636, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     self._handle_create_exception(*sys.exc_info())
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 465, in _handle_create_exception
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     six.reraise(*exc_info)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 621, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 149, in inner
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     rv = f(*args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1481, in create
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1100, in _create_instance
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     auto_disk_config, reservation_id, max_count)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 853, in _validate_and_build_base_options
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     pci_request_info, requested_networks)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 894, in create_pci_requests_for_sriov_ports
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     neutron = get_client(context, admin=True)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 205, in get_client
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     auth_token = _ADMIN_AUTH.get_token(_SESSION)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 105, in get_token
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.get_access(session).auth_token
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 145, in get_access
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     self.auth_ref = self.get_auth_ref(session)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v2.py", line 78, in get_auth_ref
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     authenticated=False, log=False)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 497, in post
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return self.request(url, 'POST', **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     return func(*args, **kwargs)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 397, in request
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack     raise exceptions.from_response(resp, method, url)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack BadRequest: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-0341863
5-5f4d-46d1-b19c-dc8148f3ffdb)
2015-05-21 11:54:12.559 23953 TRACE nova.api.openstack
2015-05-21 11:54:12.562 23953 INFO nova.api.openstack [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers returned with HTTP 500
2015-05-21 11:54:12.563 23953 INFO nova.osapi_compute.wsgi.server [req-2238fe47-69d5-4d15-a268-8d60ca62ca5a 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" status: 500 len: 359 time: 0.3005691
2015-05-21 11:54:39.929 23955 INFO nova.osapi_compute.wsgi.server [req-87cf6d0f-659c-48ba-b5b2-8a54976e80de 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/images/046e1504-27d6-4732-88e5-db2fbee4d95f HTTP/1.1" status:
200 len: 922 time: 0.9156430
2015-05-21 11:54:40.149 23955 INFO nova.osapi_compute.wsgi.server [req-f2c4a597-1ba3-4ea4-b240-6dd3e345e030 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "GET /v2/aaf543afac8143b9a4abd971325de12e/flavors/1 HTTP/1.1" status: 200 len: 639 time: 0.2103288
2015-05-21 11:54:40.450 23955 ERROR nova.api.openstack [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] Caught error: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it
is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-52f5cc08-ebd9-45bf-8031-31f530473460)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack Traceback (most recent call last):
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/__init__.py", line 125, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return req.get_response(self.application)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     application, catch_exc_info=False)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     app_iter = application(self.environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 634, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self._call_app(env, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 554, in _call_app
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self._app(env, _fake_start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     response = self.app(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return resp(environ, start_response)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     resp = self.call_func(req, *args, **self.kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.func(req, *args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 756, in __call__
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     content_type, body, accept)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 821, in _process_stack
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     action_result = self.dispatch(meth, request, action_args)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py", line 911, in dispatch
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return method(req=request, **action_args)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 636, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     self._handle_create_exception(*sys.exc_info())
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 465, in _handle_create_exception
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     six.reraise(*exc_info)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/api/openstack/compute/servers.py", line 621, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/hooks.py", line 149, in inner
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     rv = f(*args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1481, in create
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     check_server_group_quota=check_server_group_quota)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 1100, in _create_instance
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     auto_disk_config, reservation_id, max_count)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/compute/api.py", line 853, in _validate_and_build_base_options
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     pci_request_info, requested_networks)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 894, in create_pci_requests_for_sriov_ports
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     neutron = get_client(context, admin=True)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 205, in get_client
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     auth_token = _ADMIN_AUTH.get_token(_SESSION)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 105, in get_token
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.get_access(session).auth_token
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/base.py", line 145, in get_access
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     self.auth_ref = self.get_auth_ref(session)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v2.py", line 78, in get_auth_ref
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     authenticated=False, log=False)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 497, in post
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return self.request(url, 'POST', **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     return func(*args, **kwargs)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 397, in request
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack     raise exceptions.from_response(resp, method, url)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack BadRequest: Expecting to find username or userId in passwordCredentials - the server could not comply with the request since it is either malformed or otherwise incorrect. The client is assumed to be in error. (HTTP 400) (Request-ID: req-52f5cc08-ebd9-45bf-8031-31f530473460)
2015-05-21 11:54:40.450 23955 TRACE nova.api.openstack
2015-05-21 11:54:40.456 23955 INFO nova.api.openstack [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] http://bosscrm-os-controller1:8774/v2/aaf543afac8143b9a4abd971325de12e/servers returned with HTTP 500
2015-05-21 11:54:40.457 23955 INFO nova.osapi_compute.wsgi.server [req-d7d25fa5-e991-46ce-9610-3a6e7db1d396 387d1d9de32a423ebd7253b3504b1d33 aaf543afac8143b9a4abd971325de12e - - -] 10.129.253.223 "POST /v2/aaf543afac8143b9a4abd971325de12e/servers HTTP/1.1" status: 500 len: 359 time: 0.3056350

Passwords checked -

[root@bosscrm-os-controller1 httpd]# openstack --os-auth-url http://bosscrm-os-controller1:35357 --os-project-name service --os-username neutron --os-auth-type password --os-password XXXXXXXXXXXXXX token issue
+------------+----------------------------------+
| Field      | Value                            |
+------------+----------------------------------+
| expires    | 2015-05-26T16:48:12.562523Z      |
| id         | 9fd34a44d6c84d8b94088cce44b391a7 |
| project_id | f309fd9c531340b7b73f41095de6a78c |
| user_id    | dbf2a5278abd4041b31900f812ce89e1 |
+------------+----------------------------------+
[root@bosscrm-os-controller1 httpd]# openstack --os-auth-url http://bosscrm-os-controller1:35357 --os-project-name service --os-username nova --os-auth-type password --os-password XXXXXXXXXXXXXXXX token issue
+------------+----------------------------------+
| Field      | Value                            |
+------------+----------------------------------+
| expires    | 2015-05-26T16:53:24.089621Z      |
| id         | c7710c41a12b4a96bc95282687ed45ed |
| project_id | f309fd9c531340b7b73f41095de6a78c |
| user_id    | a95387ee13e949b196b341cf6aa4adf5 |
+------------+----------------------------------+