Attaching a volume to a VM generates authentication error

[Daniele Venzano]

Description
===========
When I try to attach a volume to a VM, the operation fails. From the nova logs I can see first that an authentication fails and then an "Unexpected API Error".
This happens with the "nova volume-attach" command.

The "nova volume-attachments" command works correctly.

This happens regardless of the user I use, even with a user that has the admin role.

Steps to reproduce
==================
$ nova --debug volume-attach cb22727f-32f8-49e9-8136-5395882d259a 2fe6c45f-cce9-43ea-90ac-ff0d574121b0

DEBUG (extension:180) found extension EntryPoint.parse('v1password = swiftclient.authv1:PasswordLoader')
DEBUG (extension:180) found extension EntryPoint.parse('token_endpoint = openstackclient.api.auth_plugin:TokenEndpoint')
DEBUG (extension:180) found extension EntryPoint.parse('v2token = keystoneauth1.loading._plugins.identity.v2:Token')
DEBUG (extension:180) found extension EntryPoint.parse('v3oauth1 = keystoneauth1.extras.oauth1._loading:V3OAuth1')
DEBUG (extension:180) found extension EntryPoint.parse('admin_token = keystoneauth1.loading._plugins.admin_token:AdminToken')
DEBUG (extension:180) found extension EntryPoint.parse('v3oidcauthcode = keystoneauth1.loading._plugins.identity.v3:OpenIDConnectAuthorizationCode')
DEBUG (extension:180) found extension EntryPoint.parse('v2password = keystoneauth1.loading._plugins.identity.v2:Password')
DEBUG (extension:180) found extension EntryPoint.parse('v3samlpassword = keystoneauth1.extras._saml2._loading:Saml2Password')
DEBUG (extension:180) found extension EntryPoint.parse('v3password = keystoneauth1.loading._plugins.identity.v3:Password')
DEBUG (extension:180) found extension EntryPoint.parse('v3oidcaccesstoken = keystoneauth1.loading._plugins.identity.v3:OpenIDConnectAccessToken')
DEBUG (extension:180) found extension EntryPoint.parse('v3oidcpassword = keystoneauth1.loading._plugins.identity.v3:OpenIDConnectPassword')
DEBUG (extension:180) found extension EntryPoint.parse('v3kerberos = keystoneauth1.extras.kerberos._loading:Kerberos')
DEBUG (extension:180) found extension EntryPoint.parse('token = keystoneauth1.loading._plugins.identity.generic:Token')
DEBUG (extension:180) found extension EntryPoint.parse('v3oidcclientcredentials = keystoneauth1.loading._plugins.identity.v3:OpenIDConnectClientCredentials')
DEBUG (extension:180) found extension EntryPoint.parse('v3tokenlessauth = keystoneauth1.loading._plugins.identity.v3:TokenlessAuth')
DEBUG (extension:180) found extension EntryPoint.parse('v3token = keystoneauth1.loading._plugins.identity.v3:Token')
DEBUG (extension:180) found extension EntryPoint.parse('v3totp = keystoneauth1.loading._plugins.identity.v3:TOTP')
DEBUG (extension:180) found extension EntryPoint.parse('password = keystoneauth1.loading._plugins.identity.generic:Password')
DEBUG (extension:180) found extension EntryPoint.parse('v3fedkerb = keystoneauth1.extras.kerberos._loading:MappedKerberos')
DEBUG (extension:180) found extension EntryPoint.parse('gnocchi-basic = gnocchiclient.auth:GnocchiBasicLoader')
DEBUG (extension:180) found extension EntryPoint.parse('gnocchi-noauth = gnocchiclient.auth:GnocchiNoAuthLoader')
DEBUG (extension:180) found extension EntryPoint.parse('aodh-noauth = aodhclient.noauth:AodhNoAuthLoader')
DEBUG (session:347) REQ: curl -g -i -X GET http://bfeb:35357/v3 -H "Accept: application/json" -H "User-Agent: nova keystoneauth1/2.18.0 python-requests/2.12.4 CPython/2.7.12"
DEBUG (connectionpool:212) Starting new HTTP connection (1): bfeb
DEBUG (connectionpool:400) http://bfeb:35357 "GET /v3 HTTP/1.1" 200 244
DEBUG (session:395) RESP: [200] Date: Tue, 24 Oct 2017 09:23:03 GMT Server: Apache/2.4.18 (Ubuntu) Vary: X-Auth-Token X-Distribution: Ubuntu x-openstack-request-id: req-958c9ef8-5d5c-4e
2a-9270-8048a87aab73 Content-Length: 244 Keep-Alive: timeout=5, max=100 Connection: Keep-Alive Content-Type: application/json
RESP BODY: {"version": {"status": "stable", "updated": "2017-02-22T00:00:00Z", "media-types": [{"base": "application/json", "type": "application/vnd.openstack.identity-v3+json"}], "id":
 "v3.8", "links": [{"href": "http://bfeb:35357/v3/", "rel": "self"}]}}

DEBUG (session:640) GET call to None for http://bfeb:35357/v3 used request id req-958c9ef8-5d5c-4e2a-9270-8048a87aab73
DEBUG (base:165) Making authentication request to http://bfeb:35357/v3/auth/tokens
DEBUG (connectionpool:400) http://bfeb:35357 "POST /v3/auth/tokens HTTP/1.1" 201 6571
DEBUG (base:170) {"token": {"is_domain": false, "methods": ["password"], "roles": [{"id": "783bafe0d7f0424ab906dcba69674ce9", "name": "admin"}, {"id": "88289bfc880e4265b0851ace[95/1954]
, "name": "heat_stack_owner"}], "expires_at": "2017-10-24T10:23:03.000000Z", "project": {"domain": {"id": "default", "name": "Default"}, "id": "2e51fec7c7f1408dbfe01b4eff8b6808", "name"
: "admin"}, "catalog": [{"endpoints": [{"url": "http://bfeb:9511/v1", "interface": "internal", "region": "regionOne", "region_id": "regionOne", "id": "0bc8662795d34f10a0ed48e633e3e004"}
, {"url": "http://bfeb:9511/v1", "interface": "public", "region": "regionOne", "region_id": "regionOne", "id": "68f9b5aa26ab42b480d9420d3670be10"}, {"url": "http://bfeb:9511/v1", "inter
face": "admin", "region": "regionOne", "region_id": "regionOne", "id": "f65872ee79a04c21912b097120e4d951"}], "type": "container-infra", "id": "35be9319ade845289e84dd5f6fc6d213", "name":
 "magnum"}, {"endpoints": [], "type": "metering", "id": "35f0b73e8d8d46c2b05691d474839942", "name": "ceilometer"}, {"endpoints": [{"url": "http://bfeb:8000/v1", "interface": "internal",
 "region": "regionOne", "region_id": "regionOne", "id": "25d8725364d747fea091d68dcf3955fc"}, {"url": "http://bfeb:8000/v1", "interface": "admin", "region": "regionOne", "region_id": "re
gionOne", "id": "355113aaf3c049d9b8432605b7acfa32"}, {"url": "http://bfeb:8000/v1", "interface": "public", "region": "regionOne", "region_id": "regionOne", "id": "b686e52c06f843049c20f7
a56c3b5b65"}], "type": "cloudformation", "id": "37a94b9355f742a8bf17628e846d4052", "name": "heat-cfn"}, {"endpoints": [{"url": "http://bfeb:8776/v2/2e51fec7c7f1408dbfe01b4eff8b6808", "i
nterface": "public", "region": "regionOne", "region_id": "regionOne", "id": "7234c1e8ca6746b3ace25a63908e3f80"}, {"url": "http://bfeb:8776/v2/2e51fec7c7f1408dbfe01b4eff8b6808", "interfa
ce": "admin", "region": "regionOne", "region_id": "regionOne", "id": "a8eaae32976346ccbbc5b4bc4d0852c6"}, {"url": "http://bfeb:8776/v2/2e51fec7c7f1408dbfe01b4eff8b6808", "interface": "i
nternal", "region": "regionOne", "region_id": "regionOne", "id": "da3f790d07ab47d88a0337fc5f20c674"}], "type": "volumev2", "id": "43555323f8fb4e3097a52f0c7533c8dc", "name": "cinderv2"},
 {"endpoints": [{"url": "http://bfeb:8774/v2.1/2e51fec7c7f1408dbfe01b4eff8b6808", "interface": "admin", "region": "regionOne", "region_id": "regionOne", "id": "527ddf17cf3448a0ad5525aed
0e23c85"}, {"url": "http://bfeb:8774/v2.1/2e51fec7c7f1408dbfe01b4eff8b6808", "interface": "internal", "region": "regionOne", "region_id": "regionOne", "id": "a1205a8cc6894e47b0f9e4de088
7e12d"}, {"url": "http://bfeb:8774/v2.1/2e51fec7c7f1408dbfe01b4eff8b6808", "interface": "public", "region": "regionOne", "region_id": "regionOne", "id": "df8148a45c5d40fa91021e137e35b36
2"}], "type": "compute", "id": "5aabfb54877d4836970fd97119253f72", "name": "nova"}, {"endpoints": [{"url": "http://bfeb:8778", "interface": "public", "region": "regionOne", "region_id":
 "regionOne", "id": "19b3ba83c8014d898b4ca261070ec2b2"}, {"url": "http://bfeb:8778", "interface": "internal", "region": "regionOne", "region_id": "regionOne", "id": "39591daf682b4dffb63
d859b1a57e9ad"}, {"url": "http://bfeb:8778", "interface": "admin", "region": "regionOne", "region_id": "regionOne", "id": "a84acda7878f4fd982ef3005e745a5bf"}], "type": "placement", "id"
: "5bcdb0ee6c3442c09d0cb74346b10742", "name": "placement"}, {"endpoints": [{"url": "http://bfeb:9292", "interface": "internal", "region": "regionOne", "region_id": "regionOne", "id": "0
018dc847c2e483a946ed235450dbb15"}, {"url": "http://bfeb:9292", "interface": "public", "region": "regionOne", "region_id": "regionOne", "id": "05309355982d474ea85babf29b0d333d"}, {"url":
 "http://bfeb:9292", "interface": "admin", "region": "regionOne", "region_id": "regionOne", "id": "99bf7085ed63459e8f916fa9f0f64c6a"}], "type": "image", "id": "5d4a19325cf1433ab35a07d54
221c7fa", "name": "glance"}, {"endpoints": [{"url": "http://bfeb:8004/v1/2e51fec7c7f1408dbfe01b4eff8b6808", "interface": "public", "region": "regionOne", "region_id": "regionOne", "id":
 "456a6d8cbca24debb23dc609e94200be"}, {"url": "http://bfeb:8004/v1/2e51fec7c7f1408dbfe01b4eff8b6808", "interface": "admin", "region": "regionOne", "region_id": "regionOne", "id": "797e8
aafadf84926afd3376c8a9749c7"}, {"url": "http://bfeb:8004/v1/2e51fec7c7f1408dbfe01b4eff8b6808", "interface": "internal", "region": "regionOne", "region_id": "regionOne", "id": "9f7b13cb1
43744a3b9ecec139d00ecb4"}], "type": "orchestration", "id": "7217004a3c8347489d9ecbec62abce5f", "name": "heat"}, {"endpoints": [], "type": "volume", "id": "a6b020fea87f4dafaddf654791dcbf
20", "name": "cinder"}, {"endpoints": [{"url": "http://bfeb:9696", "interface": "internal", "region": "regionOne", "region_id": "regionOne", "id": "45e72197cbcc407abdd984be99fcee61"}, {
"url": "http://bfeb:9696", "interface": "admin", "region": "regionOne", "region_id": "regionOne", "id": "77b9f3044732428483390142e63d0c82"}, {"url": "http://bfeb:9696", "interface": "pu
blic", "region": "regionOne", "region_id": "regionOne", "id": "98f758795c824dcda390bb74f255f005"}], "type": "network", "id": "d6f1333eeef6455d82ada7489b06350a", "name": "neutron"}, {"en
dpoints": [{"url": "http://bfeb:8776/v3/2e51fec7c7f1408dbfe01b4eff8b6808", "interface": "admin", "region": "regionOne", "region_id": "regionOne", "id": "5a98242bb23248d2bf53fd31c7b5de59
"}, {"url": "http://bfeb:8776/v3/2e51fec7c7f1408dbfe01b4eff8b6808", "interface": "internal", "region": "regionOne", "region_id": "regionOne", "id": "ad0dd8b63dd94aa480161f2c335e9ffa"},
{"url": "http://bfeb:8776/v3/2e51fec7c7f1408dbfe01b4eff8b6808", "interface": "public", "region": "regionOne", "region_id": "regionOne", "id": "ea1ef4fe045d4241a6411c124932ee39"}], "type
": "volumev3", "id": "e18f6330865c416cb7fe4fd02bcdf673", "name": "cinderv3"}, {"endpoints": [{"url": "http://bfeb:35357/v3/", "interface": "internal", "region": "regionOne", "region_id"
: "regionOne", "id": "2d67010656f4472cb4ea2b24781b809b"}, {"url": "http://bfeb:5000/v3/", "interface": "public", "region": "regionOne", "region_id": "regionOne", "id": "32e673ae819643c6
91deb931bc76ce50"}, {"url": "http://bfeb:35357/v3/", "interface": "admin", "region": "regionOne", "region_id": "regionOne", "id": "383c8fe6e5a641c59d9662d60ffd1494"}], "type": "identity
", "id": "e419c84ffee94673a7407eb1297e0581", "name": "keystone"}], "user": {"domain": {"id": "default", "name": "Default"}, "password_expires_at": null, "name": "admin", "id": "6468f6d8
2c734776923e367990e8a5f1"}, "audit_ids": ["yuBrTF4PTva_ig_RN_m-ZA"], "issued_at": "2017-10-24T09:23:03.000000Z"}}
REQ: curl -g -i -X GET http://bfeb:8774/v2.1/2e51fec7c7f1408dbfe01b4eff8b6808 -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}3421c89b3c57e1f96f
f3c5d9f17e62207bd72292"
DEBUG (session:347) REQ: curl -g -i -X GET http://bfeb:8774/v2.1/2e51fec7c7f1408dbfe01b4eff8b6808 -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA
1}3421c89b3c57e1f96ff3c5d9f17e62207bd72292"
DEBUG (connectionpool:212) Starting new HTTP connection (1): bfeb
DEBUG (connectionpool:400) http://bfeb:8774 "GET /v2.1/2e51fec7c7f1408dbfe01b4eff8b6808 HTTP/1.1" 404 112
RESP: [404] Content-Length: 112 Content-Type: application/json; charset=UTF-8 X-Compute-Request-Id: req-4b96f757-a50a-4fd6-b7d3-00b9127297c5 Date: Tue, 24 Oct 2017 09:23:03 GMT Connecti
on: keep-alive
RESP BODY: {"message": "The resource could not be found.<br /><br />\n\n\n", "code": "404 Not Found", "title": "Not Found"}

DEBUG (session:395) RESP: [404] Content-Length: 112 Content-Type: application/json; charset=UTF-8 X-Compute-Request-Id: req-4b96f757-a50a-4fd6-b7d3-00b9127297c5 Date: Tue, 24 Oct 2017 0
9:23:03 GMT Connection: keep-alive
RESP BODY: {"message": "The resource could not be found.<br /><br />\n\n\n", "code": "404 Not Found", "title": "Not Found"}

GET call to compute for http://bfeb:8774/v2.1/2e51fec7c7f1408dbfe01b4eff8b6808 used request id req-4b96f757-a50a-4fd6-b7d3-00b9127297c5 [45/1954]
DEBUG (session:640) GET call to compute for http://bfeb:8774/v2.1/2e51fec7c7f1408dbfe01b4eff8b6808 used request id req-4b96f757-a50a-4fd6-b7d3-00b9127297c5
REQ: curl -g -i -X GET http://bfeb:8774/v2.1/ -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}3421c89b3c57e1f96ff3c5d9f17e62207bd72292"
DEBUG (session:347) REQ: curl -g -i -X GET http://bfeb:8774/v2.1/ -H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}3421c89b3c57e1f96ff3c5d9f17e62
207bd72292"
DEBUG (connectionpool:400) http://bfeb:8774 "GET /v2.1/ HTTP/1.1" 200 378
RESP: [200] Content-Length: 378 Content-Type: application/json Openstack-Api-Version: compute 2.1 X-Openstack-Nova-Api-Version: 2.1 Vary: OpenStack-API-Version, X-OpenStack-Nova-API-Ver
sion X-Compute-Request-Id: req-66b3c7a4-0f07-4692-9172-04587445278d Date: Tue, 24 Oct 2017 09:23:03 GMT Connection: keep-alive
RESP BODY: {"version": {"status": "CURRENT", "updated": "2013-07-23T11:33:21Z", "links": [{"href": "http://bfeb:8774/v2.1/", "rel": "self"}, {"href": "http://docs.openstack.org/", "type
": "text/html", "rel": "describedby"}], "min_version": "2.1", "version": "2.42", "media-types": [{"base": "application/json", "type": "application/vnd.openstack.compute+json;version=2.1
"}], "id": "v2.1"}}

DEBUG (session:395) RESP: [200] Content-Length: 378 Content-Type: application/json Openstack-Api-Version: compute 2.1 X-Openstack-Nova-Api-Version: 2.1 Vary: OpenStack-API-Version, X-Op
enStack-Nova-API-Version X-Compute-Request-Id: req-66b3c7a4-0f07-4692-9172-04587445278d Date: Tue, 24 Oct 2017 09:23:03 GMT Connection: keep-alive
RESP BODY: {"version": {"status": "CURRENT", "updated": "2013-07-23T11:33:21Z", "links": [{"href": "http://bfeb:8774/v2.1/", "rel": "self"}, {"href": "http://docs.openstack.org/", "type
": "text/html", "rel": "describedby"}], "min_version": "2.1", "version": "2.42", "media-types": [{"base": "application/json", "type": "application/vnd.openstack.compute+json;version=2.1
"}], "id": "v2.1"}}

GET call to compute for http://bfeb:8774/v2.1/ used request id req-66b3c7a4-0f07-4692-9172-04587445278d
DEBUG (session:640) GET call to compute for http://bfeb:8774/v2.1/ used request id req-66b3c7a4-0f07-4692-9172-04587445278d
DEBUG (extension:180) found extension EntryPoint.parse('v1password = swiftclient.authv1:PasswordLoader')
DEBUG (extension:180) found extension EntryPoint.parse('token_endpoint = openstackclient.api.auth_plugin:TokenEndpoint')
DEBUG (extension:180) found extension EntryPoint.parse('v2token = keystoneauth1.loading._plugins.identity.v2:Token')
DEBUG (extension:180) found extension EntryPoint.parse('v3oauth1 = keystoneauth1.extras.oauth1._loading:V3OAuth1')
DEBUG (extension:180) found extension EntryPoint.parse('admin_token = keystoneauth1.loading._plugins.admin_token:AdminToken')
DEBUG (extension:180) found extension EntryPoint.parse('v3oidcauthcode = keystoneauth1.loading._plugins.identity.v3:OpenIDConnectAuthorizationCode')
DEBUG (extension:180) found extension EntryPoint.parse('v2password = keystoneauth1.loading._plugins.identity.v2:Password')
DEBUG (extension:180) found extension EntryPoint.parse('v3samlpassword = keystoneauth1.extras._saml2._loading:Saml2Password')
DEBUG (extension:180) found extension EntryPoint.parse('v3password = keystoneauth1.loading._plugins.identity.v3:Password')
DEBUG (extension:180) found extension EntryPoint.parse('v3oidcaccesstoken = keystoneauth1.loading._plugins.identity.v3:OpenIDConnectAccessToken')
DEBUG (extension:180) found extension EntryPoint.parse('v3oidcpassword = keystoneauth1.loading._plugins.identity.v3:OpenIDConnectPassword')
DEBUG (extension:180) found extension EntryPoint.parse('v3kerberos = keystoneauth1.extras.kerberos._loading:Kerberos')
DEBUG (extension:180) found extension EntryPoint.parse('token = keystoneauth1.loading._plugins.identity.generic:Token')
DEBUG (extension:180) found extension EntryPoint.parse('v3oidcclientcredentials = keystoneauth1.loading._plugins.identity.v3:OpenIDConnectClientCredentials')
DEBUG (extension:180) found extension EntryPoint.parse('v3tokenlessauth = keystoneauth1.loading._plugins.identity.v3:TokenlessAuth')
DEBUG (extension:180) found extension EntryPoint.parse('v3token = keystoneauth1.loading._plugins.identity.v3:Token')
DEBUG (extension:180) found extension EntryPoint.parse('v3totp = keystoneauth1.loading._plugins.identity.v3:TOTP')
DEBUG (extension:180) found extension EntryPoint.parse('password = keystoneauth1.loading._plugins.identity.generic:Password')
DEBUG (extension:180) found extension EntryPoint.parse('v3fedkerb = keystoneauth1.extras.kerberos._loading:MappedKerberos')
DEBUG (extension:180) found extension EntryPoint.parse('gnocchi-basic = gnocchiclient.auth:GnocchiBasicLoader')
DEBUG (extension:180) found extension EntryPoint.parse('gnocchi-noauth = gnocchiclient.auth:GnocchiNoAuthLoader')
DEBUG (extension:180) found extension EntryPoint.parse('aodh-noauth = aodhclient.noauth:AodhNoAuthLoader')
/usr/lib/python2.7/dist-packages/novaclient/client.py:278: UserWarning: The 'tenant_id' argument is deprecated in Ocata and its use may result in errors in future releases. As 'project_
id' is provided, the 'tenant_id' argument will be ignored.
  warnings.warn(msg)
DEBUG (session:347) REQ: curl -g -i -X GET http://bfeb:8774/v2.1/2e51fec7c7f1408dbfe01b4eff8b6808/servers/cb22727f-32f8-49e9-8136-5395882d259a -H "OpenStack-API-Version: compute 2.41" -
H "User-Agent: python-novaclient" -H "Accept: application/json" -H "X-OpenStack-Nova-API-Version: 2.41" -H "X-Auth-Token: {SHA1}3421c89b3c57e1f96ff3c5d9f17e62207bd72292"
DEBUG (connectionpool:400) http://bfeb:8774 "GET /v2.1/2e51fec7c7f1408dbfe01b4eff8b6808/servers/cb22727f-32f8-49e9-8136-5395882d259a HTTP/1.1" 200 1931
DEBUG (session:395) RESP: [200] Content-Length: 1931 Content-Type: application/json Openstack-Api-Version: compute 2.41 X-Openstack-Nova-Api-Version: 2.41 Vary: OpenStack-API-Version, X
-OpenStack-Nova-API-Version X-Compute-Request-Id: req-0ad9eddf-78c5-404f-91d8-fa412fe1ab85 Date: Tue, 24 Oct 2017 09:23:04 GMT Connection: keep-alive
RESP BODY: {"server": {"OS-EXT-STS:task_state": null, "addresses": {"flat": [{"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:9b:7e:20", "version": 4, "addr": "192.168.45.35", "OS-EXT-IPS:type": "
fixed"}]}, "links": [{"href": "http://bfeb:8774/v2.1/2e51fec7c7f1408dbfe01b4eff8b6808/servers/cb22727f-32f8-49e9-8136-5395882d259a", "rel": "self"}, {"href": "http://bfeb:8774/2e51fec7c
7f1408dbfe01b4eff8b6808/servers/cb22727f-32f8-49e9-8136-5395882d259a", "rel": "bookmark"}], "image": {"id": "a7b259f6-7c62-4a5e-861c-81f96a5d3fb7", "links": [{"href": "http://bfeb:8774/
2e51fec7c7f1408dbfe01b4eff8b6808/images/a7b259f6-7c62-4a5e-861c-81f96a5d3fb7", "rel": "bookmark"}]}, "OS-EXT-SRV-ATTR:user_data": null, "OS-EXT-STS:vm_state": "active", "OS-EXT-SRV-ATTR
:instance_name": "instance-0000112f", "OS-EXT-SRV-ATTR:root_device_name": "/dev/vda", "OS-SRV-USG:launched_at": "2017-10-19T07:17:23.000000", "flavor": {"id": "2", "links": [{"href": "h
ttp://bfeb:8774/2e51fec7c7f1408dbfe01b4eff8b6808/flavors/2", "rel": "bookmark"}]}, "id": "cb22727f-32f8-49e9-8136-5395882d259a", "OS-SRV-USG:terminated_at": null, "os-extended-volumes:v
olumes_attached": [], "user_id": "fee810060f3c48918ec95767200c788b", "OS-EXT-SRV-ATTR:hostname": "zoe", "OS-DCF:diskConfig": "AUTO", "accessIPv4": "", "accessIPv6": "", "OS-EXT-SRV-ATTR
:reservation_id": "r-t1nd7157", "progress": 0, "OS-EXT-STS:power_state": 1, "OS-EXT-AZ:availability_zone": "pool", "metadata": {}, "status": "ACTIVE", "OS-EXT-SRV-ATTR:ramdisk_id": "",
"updated": "2017-10-19T07:17:23Z", "hostId": "65bf65f5a41cbf02044f741fabe281325d698472a22e370df5b0c564", "OS-EXT-SRV-ATTR:host": "bf2", "description": "zoe", "tags": [], "key_name": "Cl
oud", "OS-EXT-SRV-ATTR:kernel_id": "", "locked": false, "OS-EXT-SRV-ATTR:hypervisor_hostname": "bf2", "name": "zoe", "OS-EXT-SRV-ATTR:launch_index": 0, "created": "2017-10-19T07:15:36Z"
, "tenant_id": "aa72257f79f44ab5a73da2bee096217c", "host_status": "UP", "config_drive": ""}}

DEBUG (session:640) GET call to compute for http://bfeb:8774/v2.1/2e51fec7c7f1408dbfe01b4eff8b6808/servers/cb22727f-32f8-49e9-8136-5395882d259a used request id req-0ad9eddf-78c5-404f-91
d8-fa412fe1ab85
DEBUG (session:347) REQ: curl -g -i -X POST http://bfeb:8774/v2.1/2e51fec7c7f1408dbfe01b4eff8b6808/servers/cb22727f-32f8-49e9-8136-5395882d259a/os-volume_attachments -H "Accept: applica
tion/json" -H "User-Agent: python-novaclient" -H "OpenStack-API-Version: compute 2.41" -H "X-OpenStack-Nova-API-Version: 2.41" -H "X-Auth-Token: {SHA1}3421c89b3c57e1f96ff3c5d9f17e62207b
d72292" -H "Content-Type: application/json" -d '{"volumeAttachment": {"volumeId": "2fe6c45f-cce9-43ea-90ac-ff0d574121b0"}}'
DEBUG (connectionpool:400) http://bfeb:8774 "POST /v2.1/2e51fec7c7f1408dbfe01b4eff8b6808/servers/cb22727f-32f8-49e9-8136-5395882d259a/os-volume_attachments HTTP/1.1" 500 210
DEBUG (session:395) RESP: [500] Openstack-Api-Version: compute 2.41 X-Openstack-Nova-Api-Version: 2.41 Vary: OpenStack-API-Version, X-OpenStack-Nova-API-Version Content-Type: applicatio
n/json; charset=UTF-8 Content-Length: 210 X-Compute-Request-Id: req-7e934a71-2236-4afa-8d38-6092d11d37fe Date: Tue, 24 Oct 2017 09:23:05 GMT Connection: keep-alive
RESP BODY: {"computeFault": {"message": "Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.\n<class 'cinderclient.excep
tions.Unauthorized'>", "code": 500}}

DEBUG (session:640) POST call to compute for http://bfeb:8774/v2.1/2e51fec7c7f1408dbfe01b4eff8b6808/servers/cb22727f-32f8-49e9-8136-5395882d259a/os-volume_attachments used request id re
q-7e934a71-2236-4afa-8d38-6092d11d37fe
DEBUG (shell:959) Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'cinderclient.exceptions.Unauthorized'> (HTTP 500) (Request-ID: req-7e934a71-2236-4afa-8d38-6092d11d37fe)
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/novaclient/shell.py", line 957, in main
    OpenStackComputeShell().main(argv)
  File "/usr/lib/python2.7/dist-packages/novaclient/shell.py", line 879, in main
    args.func(self.cs, args)
  File "/usr/lib/python2.7/dist-packages/novaclient/v2/shell.py", line 2513, in do_volume_attach
    args.device)
  File "/usr/lib/python2.7/dist-packages/novaclient/v2/volumes.py", line 53, in create_server_volume
    body, "volumeAttachment")
  File "/usr/lib/python2.7/dist-packages/novaclient/base.py", line 361, in _create
    resp, body = self.api.client.post(url, body=body)
  File "/usr/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 223, in post
    return self.request(url, 'POST', **kwargs)
  File "/usr/lib/python2.7/dist-packages/novaclient/client.py", line 80, in request
    raise exceptions.from_response(resp, body, url, method)
ClientException: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'cinderclient.exceptions.Unauthorized'> (HTTP 500) (Request-ID: req-7e934a71-2236-4afa-8d38-6092d11d37fe)
ERROR (ClientException): Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'cinderclient.exceptions.Unauthorized'> (HTTP 500) (Request-ID: req-7e934a71-2236-4afa-8d38-6092d11d37fe)

Expected result
===============
The volume is attached to the VM.

Actual result
=============
Cryptic errors are generated.

Environment
===========
1. Exact version of OpenStack you are running. See the following
  list for all releases: http://docs.openstack.org/releases/

# dpkg -l |grep nova
ii nova-api 2:15.0.6-0ubuntu1~cloud0 all OpenStack Compute - API frontend
ii nova-common 2:15.0.6-0ubuntu1~cloud0 all OpenStack Compute - common files
ii nova-conductor 2:15.0.6-0ubuntu1~cloud0 all OpenStack Compute - conductor service
ii nova-consoleauth 2:15.0.6-0ubuntu1~cloud0 all OpenStack Compute - Console Authenticator
ii nova-novncproxy 2:15.0.6-0ubuntu1~cloud0 all OpenStack Compute - NoVNC proxy
ii nova-placement-api 2:15.0.6-0ubuntu1~cloud0 all OpenStack Compute - placement API frontend
ii nova-scheduler 2:15.0.6-0ubuntu1~cloud0 all OpenStack Compute - virtual machine scheduler
ii python-nova 2:15.0.6-0ubuntu1~cloud0 all OpenStack Compute Python libraries
ii python-novaclient 2:7.1.0-0ubuntu1~cloud0 all client library for OpenStack Compute API - Python 2.7

2. Which hypervisor did you use?
Libvirt + KVM

2. Which storage type did you use?
Ceph

3. Which networking type did you use?
Neutron flat network

Logs & Configs
==============
Relevant part of the nova-api.log

2017-10-24 11:23:03.320 18537 DEBUG nova.osapi_compute.wsgi.server [req-ba39611c-6ea1-4abf-ae25-786dd1f42082 - - - - -] (18537) accepted ('192.168.46.26', 36478) server /usr/lib/python2
.7/dist-packages/eventlet/wsgi.py:867
2017-10-24 11:23:03.377 18537 INFO nova.osapi_compute.wsgi.server [req-4b96f757-a50a-4fd6-b7d3-00b9127297c5 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default d
efault] 192.168.46.26 "GET /v2.1/2e51fec7c7f1408dbfe01b4eff8b6808 HTTP/1.1" status: 404 len: 331 time: 0.0551920
2017-10-24 11:23:03.391 18537 DEBUG nova.api.openstack.wsgi [req-66b3c7a4-0f07-4692-9172-04587445278d 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default
] Calling method '<bound method VersionsController.show of <nova.api.openstack.compute.versionsV21.VersionsController object at 0x7ff888997a50>>' _process_stack /usr/lib/python2.7/dist-
packages/nova/api/openstack/wsgi.py:626
2017-10-24 11:23:03.393 18537 INFO nova.osapi_compute.wsgi.server [req-66b3c7a4-0f07-4692-9172-04587445278d 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default d
efault] 192.168.46.26 "GET /v2.1/ HTTP/1.1" status: 200 len: 711 time: 0.0120900
2017-10-24 11:23:03.606 18537 DEBUG nova.api.openstack.wsgi [req-0ad9eddf-78c5-404f-91d8-fa412fe1ab85 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default
] Calling method '<bound method ServersController.show of <nova.api.openstack.compute.servers.ServersController object at 0x7ff888a4bfd0>>' _process_stack /usr/lib/python2.7/dist-packag
es/nova/api/openstack/wsgi.py:626
2017-10-24 11:23:03.614 18537 DEBUG nova.compute.api [req-0ad9eddf-78c5-404f-91d8-fa412fe1ab85 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] [inst
ance: cb22727f-32f8-49e9-8136-5395882d259a] Fetching instance by UUID get /usr/lib/python2.7/dist-packages/nova/compute/api.py:2360
2017-10-24 11:23:03.640 18537 DEBUG oslo_db.sqlalchemy.engines [req-0ad9eddf-78c5-404f-91d8-fa412fe1ab85 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default defa
ult] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION _check
_effective_sql_mode /usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:261
2017-10-24 11:23:03.654 18537 DEBUG oslo_concurrency.lockutils [req-0ad9eddf-78c5-404f-91d8-fa412fe1ab85 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default defa
ult] Lock "02388e9f-5aab-4301-bc69-ddca16a3ccfb" acquired by "nova.context.get_or_set_cached_cell_and_set_connections" :: waited 0.000s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:273
2017-10-24 11:23:03.655 18537 DEBUG oslo_concurrency.lockutils [req-0ad9eddf-78c5-404f-91d8-fa412fe1ab85 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] Lock "02388e9f-5aab-4301-bc69-ddca16a3ccfb" released by "nova.context.get_or_set_cached_cell_and_set_connections" :: held 0.001s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:285
2017-10-24 11:23:03.668 18537 DEBUG oslo_db.sqlalchemy.engines [req-0ad9eddf-78c5-404f-91d8-fa412fe1ab85 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION _check_effective_sql_mode /usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:261
2017-10-24 11:23:03.790 18537 DEBUG nova.objects.instance [req-0ad9eddf-78c5-404f-91d8-fa412fe1ab85 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] Lazy-loading 'services' on Instance uuid cb22727f-32f8-49e9-8136-5395882d259a obj_load_attr /usr/lib/python2.7/dist-packages/nova/objects/instance.py:1034
2017-10-24 11:23:04.594 18537 DEBUG neutronclient.v2_0.client [req-0ad9eddf-78c5-404f-91d8-fa412fe1ab85 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] GET call to neutron for http://bfeb:9696/v2.0/ports.json?device_id=cb22727f-32f8-49e9-8136-5395882d259a used request id req-8aaaa9ad-f1ba-43ac-b9dc-bb97a050a1d1 _append_request_id /usr/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
2017-10-24 11:23:04.620 18537 DEBUG nova.policy [req-0ad9eddf-78c5-404f-91d8-fa412fe1ab85 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] Policy check for os_compute_api:os-hide-server-addresses failed with credentials {'service_roles': [], 'user_id': u'6468f6d82c734776923e367990e8a5f1', 'roles': [u'admin', u'heat_stack_owner'], 'user_domain_id': u'default', 'service_project_id': None, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_domain_id': None, 'is_admin_project': True, 'is_admin': True, 'project_id': u'2e51fec7c7f1408dbfe01b4eff8b6808', 'project_domain_id': u'default'} authorize /usr/lib/python2.7/dist-packages/nova/policy.py:168
2017-10-24 11:23:04.695 18537 INFO nova.osapi_compute.wsgi.server [req-0ad9eddf-78c5-404f-91d8-fa412fe1ab85 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] 192.168.46.26 "GET /v2.1/2e51fec7c7f1408dbfe01b4eff8b6808/servers/cb22727f-32f8-49e9-8136-5395882d259a HTTP/1.1" status: 200 len: 2267 time: 1.1006789
2017-10-24 11:23:04.725 18537 DEBUG nova.api.openstack.wsgi [req-7e934a71-2236-4afa-8d38-6092d11d37fe 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] Action: 'create', calling method: <bound method VolumeAttachmentController.create of <nova.api.openstack.compute.volumes.VolumeAttachmentController object at 0x7ff88884a090>>, body: {"volumeAttachment": {"volumeId": "2fe6c45f-cce9-43ea-90ac-ff0d574121b0"}} _process_stack /usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py:623
2017-10-24 11:23:04.741 18537 DEBUG nova.compute.api [req-7e934a71-2236-4afa-8d38-6092d11d37fe 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] [instance: cb22727f-32f8-49e9-8136-5395882d259a] Fetching instance by UUID get /usr/lib/python2.7/dist-packages/nova/compute/api.py:2360
2017-10-24 11:23:04.760 18537 DEBUG oslo_concurrency.lockutils [req-7e934a71-2236-4afa-8d38-6092d11d37fe 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] Lock "02388e9f-5aab-4301-bc69-ddca16a3ccfb" acquired by "nova.context.get_or_set_cached_cell_and_set_connections" :: waited 0.000s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:273
2017-10-24 11:23:04.761 18537 DEBUG oslo_concurrency.lockutils [req-7e934a71-2236-4afa-8d38-6092d11d37fe 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] Lock "02388e9f-5aab-4301-bc69-ddca16a3ccfb" released by "nova.context.get_or_set_cached_cell_and_set_connections" :: held 0.001s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:285
2017-10-24 11:23:04.908 18537 DEBUG oslo_messaging._drivers.amqpdriver [req-7e934a71-2236-4afa-8d38-6092d11d37fe 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] CALL msg_id: 259736aee2ca45569a84b1b1acced5f3 exchange 'nova' topic 'compute.bf2' _send /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:442
2017-10-24 11:23:05.043 18537 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 259736aee2ca45569a84b1b1acced5f3 __call__ /usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:299
2017-10-24 11:23:05.061 18537 DEBUG cinderclient.v2.client [req-7e934a71-2236-4afa-8d38-6092d11d37fe 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] REQ: curl -g -i -X GET http://bfeb:8776/v2/2e51fec7c7f1408dbfe01b4eff8b6808/volumes/2fe6c45f-cce9-43ea-90ac-ff0d574121b0 -H "X-Service-Token: {SHA1}00e767c36ea5c08c4f5e4dbdbbe788da449a1990" -H "User-Agent: python-cinderclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}3421c89b3c57e1f96ff3c5d9f17e62207bd72292" _http_log_request /usr/lib/python2.7/dist-packages/keystoneauth1/session.py:347
2017-10-24 11:23:05.069 18537 DEBUG cinderclient.v2.client [req-7e934a71-2236-4afa-8d38-6092d11d37fe 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] RESP: [401] Date: Tue, 24 Oct 2017 09:23:05 GMT Server: Apache/2.4.18 (Ubuntu) x-openstack-request-id: req-f8ce808c-bcae-4729-a48d-2ebd997fd521 WWW-Authenticate: Keystone uri='http://bfeb:5000' Content-Length: 114 Keep-Alive: timeout=5, max=100 Connection: Keep-Alive Content-Type: application/json
RESP BODY: {"error": {"message": "The request you have made requires authentication.", "code": 401, "title": "Unauthorized"}}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneauth1/session.py:395
2017-10-24 11:23:05.069 18537 DEBUG cinderclient.v2.client [req-7e934a71-2236-4afa-8d38-6092d11d37fe 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] GET call to cinderv2 for http://bfeb:8776/v2/2e51fec7c7f1408dbfe01b4eff8b6808/volumes/2fe6c45f-cce9-43ea-90ac-ff0d574121b0 used request id req-f8ce808c-bcae-4729-a48d-2ebd997fd521 request /usr/lib/python2.7/dist-packages/keystoneauth1/session.py:640
2017-10-24 11:23:05.075 18537 DEBUG cinderclient.v2.client [req-7e934a71-2236-4afa-8d38-6092d11d37fe 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] RESP: [401] Date: Tue, 24 Oct 2017 09:23:05 GMT Server: Apache/2.4.18 (Ubuntu) x-openstack-request-id: req-993ee979-8659-4afd-9db5-e858808d432a WWW-Authenticate: Keystone uri='http://bfeb:5000' Content-Length: 114 Keep-Alive: timeout=5, max=99 Connection: Keep-Alive Content-Type: application/json
RESP BODY: {"error": {"message": "The request you have made requires authentication.", "code": 401, "title": "Unauthorized"}}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneauth1/session.py:395
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions [req-7e934a71-2236-4afa-8d38-6092d11d37fe 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] Unexpected exception in API method
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions Traceback (most recent call last):
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/api/openstack/extensions.py", line 338, in wrapped
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions return f(*args, **kwargs)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/api/validation/__init__.py", line 108, in wrapper
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions return func(*args, **kwargs)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/api/openstack/compute/volumes.py", line 326, in create
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions volume_id, device)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 170, in inner
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions return function(self, context, instance, *args, **kwargs)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 151, in inner
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions return f(self, context, instance, *args, **kw)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 3701, in attach_volume
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions disk_bus, device_type)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 3644, in _attach_volume
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions volume_bdm.destroy()
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions self.force_reraise()
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions six.reraise(self.type_, self.value, self.tb)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 3640, in _attach_volume
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions self._check_attach_and_reserve_volume(context, volume_id, instance)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 3624, in _check_attach_and_reserve_volume
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions volume = self.volume_api.get(context, volume_id)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/volume/cinder.py", line 168, in wrapper
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions res = method(self, ctx, *args, **kwargs)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/volume/cinder.py", line 190, in wrapper
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions res = method(self, ctx, volume_id, *args, **kwargs)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/nova/volume/cinder.py", line 234, in get
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions item = cinderclient(context).volumes.get(volume_id)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/cinderclient/v2/volumes.py", line 277, in get
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions return self._get("/volumes/%s" % volume_id, "volume")
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/cinderclient/base.py", line 313, in _get
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions resp, body = self.api.client.get(url)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/cinderclient/client.py", line 164, in get
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions return self._cs_request(url, 'GET', **kwargs)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/cinderclient/client.py", line 155, in _cs_request
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions return self.request(url, method, **kwargs)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions File "/usr/lib/python2.7/dist-packages/cinderclient/client.py", line 144, in request
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions raise exceptions.from_response(resp, body)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions Unauthorized: The request you have made requires authentication. (HTTP 401)
2017-10-24 11:23:05.084 18537 ERROR nova.api.openstack.extensions
2017-10-24 11:23:05.088 18537 INFO nova.api.openstack.wsgi [req-7e934a71-2236-4afa-8d38-6092d11d37fe 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] HTTP exception thrown: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'cinderclient.exceptions.Unauthorized'>
2017-10-24 11:23:05.089 18537 DEBUG nova.api.openstack.wsgi [req-7e934a71-2236-4afa-8d38-6092d11d37fe 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] Returning 500 to user: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'cinderclient.exceptions.Unauthorized'> __call__ /usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py:1039
2017-10-24 11:23:05.091 18537 INFO nova.osapi_compute.wsgi.server [req-7e934a71-2236-4afa-8d38-6092d11d37fe 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] 192.168.46.26 "POST /v2.1/2e51fec7c7f1408dbfe01b4eff8b6808/servers/cb22727f-32f8-49e9-8136-5395882d259a/os-volume_attachments HTTP/1.1" status: 500 len: 579 time: 0.3905520

[Daniele Venzano (venza)]

Please note that creating a VM on a volume works correctly, too.
It's just attaching an existing volume to an existing VM that is failing.

[Matt Riedemann (mriedem)]

You're sure the [cinder] configuration in nova.conf is correct so that the nova user can communicate with the block storage service?

Nova is making a GET /volumes request to Cinder to get volume details and that's failing:

REQ: curl -g -i -X GET http://bfeb:8776/v2/2e51fec7c7f1408dbfe01b4eff8b6808/volumes/2fe6c45f-cce9-43ea-90ac-ff0d574121b0 -H "X-Service-Token: {SHA1}00e767c36ea5c08c4f5e4dbdbbe788da449a1990" -H "User-Agent: python-cinderclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}3421c89b3c57e1f96ff3c5d9f17e62207bd72292" _http_log_request /usr/lib/python2.7/dist-packages/keystoneauth1/session.py:347
2017-10-24 11:23:05.069 18537 DEBUG cinderclient.v2.client [req-7e934a71-2236-4afa-8d38-6092d11d37fe 6468f6d82c734776923e367990e8a5f1 2e51fec7c7f1408dbfe01b4eff8b6808 - default default] RESP: [401] Date: Tue, 24 Oct 2017 09:23:05 GMT Server: Apache/2.4.18 (Ubuntu) x-openstack-request-id: req-f8ce808c-bcae-4729-a48d-2ebd997fd521 WWW-Authenticate: Keystone uri='http://bfeb:5000' Content-Length: 114 Keep-Alive: timeout=5, max=100 Connection: Keep-Alive Content-Type: application/json
RESP BODY: {"error": {"message": "The request you have made requires authentication.", "code": 401, "title": "Unauthorized"}}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneauth1/session.py:395

Which implies the credentials that nova.conf is using are wrong for talking to cinder - are there errors in the keystone logs for that request?

[Daniele Venzano (venza)]

in my nova.conf I have just the following:

[cinder]
catalog_info=volumev2:cinderv2:internalURL
os_region_name=regionOne

(the region name is correct)

I followed this documentation:
https://docs.openstack.org/ocata/install-guide-ubuntu/cinder-controller-install.html

Also in the template configuration file that comes with the package there is no mention of other options related to authentication.

[Sylvain Bauza (sylvain-bauza)]

Are you sure your [keystone_authtoken] section is valid as well ?

[Daniele Venzano (venza)]

Yes, they are valid.
Meaning that if I use the credentials I have in the [keystone_authtoken] section of nova.conf to login to keystone, it succeeds.

Everything works as expected, the dashboard, Glance, I see all the compute nodes and I can spawn VMs on them. I can even start VMs on volumes and it works.

It is only attaching a volume to a VM that fails with the error above.

[Matt Riedemann (mriedem)]

Did you ever get to the bottom of this? I misled you a bit in comment 2 since before queens, there was no auth configuration for the [cinder] section of nova.conf, it should just be using the token from the request context when attaching the volume.

[Jim Kilborn (jkilborn)]

I'm experiencing this same issue with pike. VM's create fine with volume backed storage. Creating a new volume works fine, but attaching an existing volume to an existing vm fails with the same error.

DEBUG (shell:951) Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'cinderclient.exceptions.Unauthorized'> (HTTP 500) (Request-ID: req-57b8b949-f781-4620-9225-098a51dfa8f2)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/novaclient/shell.py", line 949, in main
    OpenStackComputeShell().main(argv)
  File "/usr/lib/python2.7/site-packages/novaclient/shell.py", line 871, in main
    args.func(self.cs, args)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/shell.py", line 2370, in do_volume_attach
    **update_kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/api_versions.py", line 393, in substitution
    return methods[-1].func(obj, *args, **kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/v2/volumes.py", line 76, in create_server_volume
    body, "volumeAttachment")
  File "/usr/lib/python2.7/site-packages/novaclient/base.py", line 361, in _create
    resp, body = self.api.client.post(url, body=body)
  File "/usr/lib/python2.7/site-packages/keystoneauth1/adapter.py", line 294, in post
    return self.request(url, 'POST', **kwargs)
  File "/usr/lib/python2.7/site-packages/novaclient/client.py", line 83, in request
    raise exceptions.from_response(resp, body, url, method)
ClientException: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'cinderclient.exceptions.Unauthorized'> (HTTP 500) (Request-ID: req-57b8b949-f781-4620-9225-098a51dfa8f2)
ERROR (ClientException): Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'cinderclient.exceptions.Unauthorized'> (HTTP 500) (Request-ID: req-57b8b949-f781-4620-9225-098a51dfa8f2)

[Jim Kilborn (jkilborn)]

My issue was resolved by setting service_token_roles_required to false in both the cinder.conf and nova.conf

[Matt Riedemann (mriedem)]

Hmm, were there errors in the keystone logs that tipped you off to anything with service_token_roles_required?

https://docs.openstack.org/nova/latest/configuration/config.html#keystone_authtoken.service_token_roles_required

Is there something different about the user / project that is creating the volume vs attaching the volume?

[Launchpad Janitor (janitor)]

[Expired for OpenStack Compute (nova) because there has been no activity for 60 days.]

[Daniele Venzano (venza)]

I confirm that the problem is still there in Pike and that it is solved by setting service_token_roles_required to false

Since it is a deprecated configuration this is a workaround, but not a solution.

Since there is no explicit auth section for Cinder, like there is for Neutron, it is using the auth token from the user ?

Simple situation, the same user does everything via the web dashboard.
Creates a VM, creates a volume, attaches it.

Which token/auth is used? The one from the user? So if I try to connect to Cinder directly (via the command line client for example) as the user, I should get the same error? Uhm, no it works.

I tried enabling the service_user stuff, but it doesn't help.

Perhaps something in the policy that prevent attaching volumes?