server add volume fails

Description
===========
<class 'cinderclient.exceptions.Unauthorized'> (HTTP 500)
It seems to start by not finding the instance in nova.

Environment
===========

Environment: (Rocky)
openstack-nova-common-18.3.0-1.el7.noarch
openstack-nova-conductor-18.3.0-1.el7.noarch
openstack-nova-api-18.3.0-1.el7.noarch
openstack-nova-scheduler-18.3.0-1.el7.noarch
openstack-nova-console-18.3.0-1.el7.noarch
openstack-nova-placement-api-18.3.0-1.el7.noarch
python2-novaclient-11.0.1-1.el7.noarch
openstack-nova-novncproxy-18.3.0-1.el7.noarch
python-nova-18.3.0-1.el7.noarch

Hypervisor:
Linux KVM

Storate:
CEPH: 14.2.8 / RBD volumes

Network:
Neutron (OpenVSwitch)

Steps to reproduce
==================

I did: openstack --debug server add volume c331814d-b758-460e-9972-bc1e987b933d 0fc5bec7-9364-458c-a809-f38389890a60

I also did: openstack --debug server add volume allalal peter-test-001

I received:

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-fb493f88-61c5-4ebd-829b-305b31aaa010)

Expected result
===============
Associate the volume and exit cleanly.

Actual result
=============
Nova fails to find existing instance and fails the attempt to add the volume. All other server commands for the instance work as expected (stop, start, migrate, etc.)

Logs & Configs
==============
/etc/nova/nova.conf
[DEFAULT]
cpu_allocation_ratio = 16.0
debug = true
enabled_apis = osapi_compute,metadata
metadata_proxy_shared_secret = <secret>
metadata_workers = 4
my_ip = 10.176.0.42
ram_allocation_ratio = 1.0
scheduler_host_subset_size = 2
transport_url = rabbit://openstack:<passwd>@mq-a01.xxx.cloud,openstack:<passwd>@mq-a02.xxx.cloud,openstack:<passwd>@mq-a03.xxx.cloud
cinder_catalog_info=volumev3:cinderv3:publicURL

[api]
auth_strategy = keystone

[api_database]
connection = mysql+pymysql://atx_nova_api:<passwd>@db-a00.xxx.cloud/atx_nova_api

[filter_scheduler]
enabled_filters = AvailabilityZoneFilter,ComputeCapabilitiesFilter,ComputeFilter,ImagePropertiesFilter,RamFilter,RetryFilter,ServerGroupAffinityFilter,ServerGroupAntiAffinityFilter
host_subset_size = 4
io_ops_weight_multiplier = 10.0
max_instances_per_host = 100
ram_weight_multiplier = 6.0
soft_affinity_weight_multiplier = 10.0
soft_anti_affinity_weight_multiplier = 10.0
weight_classes = nova.scheduler.weights.all_weighers

[database]
connection = mysql+pymysql://atx_nova:<passwd>@db-a00.xxx.cloud/atx_nova

[glance]
api_servers = https://glance-a00.xxx.cloud

[keystone_authtoken]
auth_type = password
www_authenticate_uri = https://keystone-a00.xxx.cloud
auth_url = https://keystone-a00.xxx.cloud
memcached_servers = memcached-a01.xxx.cloud:11211,memcached-a02.xxx.cloud:11211,memcached-a03.xxx.cloud:11211
password = <passwd>
project_domain_name = default
project_name = service
user_domain_name = default
username = atx_nova
service_token_roles_required = true

[neutron]
auth_type = password
auth_url = https://keystone-a00.xxx.cloud
metadata_proxy_shared_secret = <secret>
password = <passwd>
project_domain_name = Default
project_name = service
region_name = atx
service_metadata_proxy = true
#uses keystoneauth1: url = https://neutron-a00.xxx.cloud
user_domain_name = Default
username = atx_neutron

[oslo_concurrency]
lock_path = /var/lib/nova/tmp

[placement]
auth_type = password
auth_url = https://keystone-a00.xxx.cloud
os_region_name = atx
password = <passwd>
project_domain_name = Default
project_name = service
user_domain_name = Default
username = atx_placement

[scheduler]
discover_hosts_in_cells_interval = 300

[oslo_notifications_group]
driver = messaging
topics = notifications

[cache]
backend=oslo_cache.memcache_pool
enable = true

[oslo_messaging_rabbit]
amqp_durable_queues = true
rabbit_ha_queues = true
rabbit_retry_backoff = 2
rabbit_retry_interval = 1

[peisch@jump ~]$ openstack volume list
+--------------------------------------+----------------+-----------+------+-------------+
| ID | Name | Status | Size | Attached to |
+--------------------------------------+----------------+-----------+------+-------------+
| ... | ... | available | 10 | |
| 0fc5bec7-9364-458c-a809-f38389890a60 | peter-test-001 | available | 10 | |
| ... | ... | available | 10 | |
+--------------------------------------+----------------+-----------+------+-------------+
[peisch@hopslam ~]$ openstack server list
+--------------------------------------+-----------+--------+---------------------+----------+--------+
| ID | Name | Status | Networks | Image | Flavor |
+--------------------------------------+-----------+--------+---------------------+----------+--------+
| ... | ... | ACTIVE | admin=10.1.2.5 | Centos77 | 2x2x20 |
| c331814d-b758-460e-9972-bc1e987b933d | allalal | ACTIVE | admin=10.1.2.7 | Centos77 | 2x2x20 |
+--------------------------------------+-----------+--------+---------------------+----------+--------+
[peisch@jump ~]$

Openstack Debug Log:
(starting after keystone auth)
Starting new HTTPS connection (1): nova-a00.xxx.cloud
https://nova-a00.xxx.cloud:443 "GET /v2.1/servers/c331814d-b758-460e-9972-bc1e987b933d HTTP/1.1" 200 1646
RESP: [200] Content-Length: 1646 Content-Type: application/json Date: Wed, 13 May 2020 19:39:35 GMT Openstack-Api-Version: compute 2.1 Vary: OpenStack-API-Version, X-OpenStack-Nova-API-Version X-Compute-Request-Id: req-a98e058c-27df-471a-9553-8f9f52dab060 X-Openstack-Nova-Api-Version: 2.1 X-Openstack-Request-Id: req-a98e058c-27df-471a-9553-8f9f52dab060
RESP BODY: {"server": {"OS-EXT-STS:task_state": null, "addresses": {"admin": [{"OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:a3:6a:5c", "version": 4, "addr": "10.176.128.7", "OS-EXT-IPS:type": "fixed"}]}, "links": [{"href": "http://nova-a00.xxx.cloud/v2.1/servers/c331814d-b758-460e-9972-bc1e987b933d", "rel": "self"}, {"href": "http://nova-a00.xxx.cloud/servers/c331814d-b758-460e-9972-bc1e987b933d", "rel": "bookmark"}], "image": {"id": "41bb501b-907e-4e0f-a9fe-072a5d3fbe58", "links": [{"href": "http://nova-a00.xxx.cloud/images/41bb501b-907e-4e0f-a9fe-072a5d3fbe58", "rel": "bookmark"}]}, "OS-EXT-STS:vm_state": "active", "OS-EXT-SRV-ATTR:instance_name": "instance-00000601", "OS-SRV-USG:launched_at": "2020-04-27T20:44:42.000000", "flavor": {"id": "d15ae531-2911-4c5a-aeb5-d62081def56d", "links": [{"href": "http://nova-a00.xxx.cloud/flavors/d15ae531-2911-4c5a-aeb5-d62081def56d", "rel": "bookmark"}]}, "id": "c331814d-b758-460e-9972-bc1e987b933d", "security_groups": [{"name": "default"}], "user_id": "497a19c5da034431b6c01d5d8f523968", "OS-DCF:diskConfig": "MANUAL", "accessIPv4": "", "accessIPv6": "", "progress": 0, "OS-EXT-STS:power_state": 1, "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "status": "ACTIVE", "updated": "2020-04-27T20:45:57Z", "hostId": "d98666c745c89cc71a5fa952c75899cc9bd67808a24a117dc5054f5b", "OS-EXT-SRV-ATTR:host": "compute-a19.xxx.cloud", "OS-SRV-USG:terminated_at": null, "key_name": null, "OS-EXT-SRV-ATTR:hypervisor_hostname": "compute-a19.xxx.cloud", "name": "allalal", "created": "2020-04-24T14:51:33Z", "tenant_id": "1134ba6f01ef43f49961aa6bbe49f5bc", "os-extended-volumes:volumes_attached": [], "metadata": {}}}
GET call to compute for https://nova-a00.xxx.cloud/v2.1/servers/c331814d-b758-460e-9972-bc1e987b933d used request id req-a98e058c-27df-471a-9553-8f9f52dab060
REQ: curl -g -i -X GET https://cinder-a00.xxx.cloud/v3/1134ba6f01ef43f49961aa6bbe49f5bc/volumes/0fc5bec7-9364-458c-a809-f38389890a60 -H "Accept: application/json" -H "User-Agent: python-cinderclient" -H "X-Auth-Token: {SHA1}99c93352a2ccbc3dd1f8df8997f0469a95f9f367"
Starting new HTTPS connection (1): cinder-a00.xxx.cloud
https://cinder-a00.xxx.cloud:443 "GET /v3/1134ba6f01ef43f49961aa6bbe49f5bc/volumes/0fc5bec7-9364-458c-a809-f38389890a60 HTTP/1.1" 200 1055
RESP: [200] Content-Length: 1055 Content-Type: application/json Date: Wed, 13 May 2020 19:39:35 GMT Openstack-Api-Version: volume 3.0 Vary: OpenStack-API-Version X-Compute-Request-Id: req-c192e90e-711d-498e-806d-1eeded367306 X-Openstack-Request-Id: req-c192e90e-711d-498e-806d-1eeded367306
RESP BODY: {"volume": {"migration_status": null, "attachments": [], "links": [{"href": "https://cinder-a00.xxx.cloud/v3/1134ba6f01ef43f49961aa6bbe49f5bc/volumes/0fc5bec7-9364-458c-a809-f38389890a60", "rel": "self"}, {"href": "https://cinder-a00.xxx.cloud/1134ba6f01ef43f49961aa6bbe49f5bc/volumes/0fc5bec7-9364-458c-a809-f38389890a60", "rel": "bookmark"}], "availability_zone": "nova", "os-vol-host-attr:host": "cinder-a03.xxx.cloud@sizeone#sizeone", "encrypted": false, "updated_at": "2020-04-24T14:52:25.000000", "replication_status": null, "snapshot_id": null, "id": "0fc5bec7-9364-458c-a809-f38389890a60", "size": 10, "user_id": "497a19c5da034431b6c01d5d8f523968", "os-vol-tenant-attr:tenant_id": "1134ba6f01ef43f49961aa6bbe49f5bc", "os-vol-mig-status-attr:migstat": null, "metadata": {}, "status": "available", "description": null, "multiattach": false, "source_volid": null, "consistencygroup_id": null, "os-vol-mig-status-attr:name_id": null, "name": "peter-test-001", "bootable": "false", "created_at": "2020-04-24T14:52:24.000000", "volume_type": "sizeone"}}
GET call to volumev3 for https://cinder-a00.xxx.cloud/v3/1134ba6f01ef43f49961aa6bbe49f5bc/volumes/0fc5bec7-9364-458c-a809-f38389890a60 used request id req-c192e90e-711d-498e-806d-1eeded367306
REQ: curl -g -i -X POST https://nova-a00.xxx.cloud/v2.1/servers/c331814d-b758-460e-9972-bc1e987b933d/os-volume_attachments -H "Accept: application/json" -H "Content-Type: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: {SHA1}99c93352a2ccbc3dd1f8df8997f0469a95f9f367" -d '{"volumeAttachment": {"volumeId": "0fc5bec7-9364-458c-a809-f38389890a60"}}'
https://nova-a00.xxx.cloud:443 "POST /v2.1/servers/c331814d-b758-460e-9972-bc1e987b933d/os-volume_attachments HTTP/1.1" 500 210
RESP: [500] Content-Length: 210 Content-Type: application/json; charset=UTF-8 Date: Wed, 13 May 2020 19:39:36 GMT Openstack-Api-Version: compute 2.1 Vary: OpenStack-API-Version, X-OpenStack-Nova-API-Version X-Compute-Request-Id: req-fb493f88-61c5-4ebd-829b-305b31aaa010 X-Openstack-Nova-Api-Version: 2.1 X-Openstack-Request-Id: req-fb493f88-61c5-4ebd-829b-305b31aaa010
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.exceptions.Unauthorized'>", "code": 500}}
POST call to compute for https://nova-a00.xxx.cloud/v2.1/servers/c331814d-b758-460e-9972-bc1e987b933d/os-volume_attachments used request id req-fb493f88-61c5-4ebd-829b-305b31aaa010
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-fb493f88-61c5-4ebd-829b-305b31aaa010)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/cliff/app.py", line 402, in run_subcommand
    result = cmd.run(parsed_args)
  File "/usr/lib/python2.7/site-packages/osc_lib/command/command.py", line 41, in run
    return super(Command, self).run(parsed_args)
  File "/usr/lib/python2.7/site-packages/cliff/command.py", line 184, in run
    return_code = self.take_action(parsed_args) or 0
  File "/usr/lib/python2.7/site-packages/openstackclient/compute/v2/server.py", line 464, in take_action
    parsed_args.device,
  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 56, 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 334, 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-fb493f88-61c5-4ebd-829b-305b31aaa010)
clean_up AddServerVolume: 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-fb493f88-61c5-4ebd-829b-305b31aaa010)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/osc_lib/shell.py", line 135, in run
    ret_val = super(OpenStackShell, self).run(argv)
  File "/usr/lib/python2.7/site-packages/cliff/app.py", line 281, in run
    result = self.run_subcommand(remainder)
  File "/usr/lib/python2.7/site-packages/osc_lib/shell.py", line 175, in run_subcommand
    ret_value = super(OpenStackShell, self).run_subcommand(argv)
  File "/usr/lib/python2.7/site-packages/cliff/app.py", line 402, in run_subcommand
    result = cmd.run(parsed_args)
  File "/usr/lib/python2.7/site-packages/osc_lib/command/command.py", line 41, in run
    return super(Command, self).run(parsed_args)
  File "/usr/lib/python2.7/site-packages/cliff/command.py", line 184, in run
    return_code = self.take_action(parsed_args) or 0
  File "/usr/lib/python2.7/site-packages/openstackclient/compute/v2/server.py", line 464, in take_action
    parsed_args.device,
  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 56, 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 334, 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-fb493f88-61c5-4ebd-829b-305b31aaa010)

END return value: 1

==> /var/log/nova/nova-api.log <==
2020-05-13 13:59:06.159 14830 DEBUG nova.api.openstack.wsgi [req-1299524b-1fb1-46b1-82de-9d3ced5c694f c351f9a7674a4a0cbe63ca633f66f606 1134ba6f01ef43f49961aa6bbe49f5bc - default default] Action: 'create', calling method: <bound method VolumeAttachmentController.create of <nova.api.openstack.compute.volumes.VolumeAttachmentController object at 0x7f5113d97050>>, body: {"volumeAttachment": {"volumeId": "0fc5bec7-9364-458c-a809-f38389890a60"}} _process_stack /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:615
2020-05-13 13:59:06.163 14830 DEBUG nova.compute.api [req-1299524b-1fb1-46b1-82de-9d3ced5c694f c351f9a7674a4a0cbe63ca633f66f606 1134ba6f01ef43f49961aa6bbe49f5bc - default default] [instance: c331814d-b758-460e-9972-bc1e987b933d] Fetching instance by UUID get /usr/lib/python2.7/site-packages/nova/compute/api.py:2421
2020-05-13 13:59:06.171 14830 DEBUG oslo_concurrency.lockutils [req-1299524b-1fb1-46b1-82de-9d3ced5c694f c351f9a7674a4a0cbe63ca633f66f606 1134ba6f01ef43f49961aa6bbe49f5bc - default default] Lock "3bc099c6-6bc5-4d39-9259-3c2fca30c75e" acquired by "nova.context.get_or_set_cached_cell_and_set_connections" :: waited 0.000s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273
2020-05-13 13:59:06.171 14830 DEBUG oslo_concurrency.lockutils [req-1299524b-1fb1-46b1-82de-9d3ced5c694f c351f9a7674a4a0cbe63ca633f66f606 1134ba6f01ef43f49961aa6bbe49f5bc - default default] Lock "3bc099c6-6bc5-4d39-9259-3c2fca30c75e" released by "nova.context.get_or_set_cached_cell_and_set_connections" :: held 0.001s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285
2020-05-13 13:59:07.223 14830 INFO nova.api.openstack.wsgi [req-1299524b-1fb1-46b1-82de-9d3ced5c694f c351f9a7674a4a0cbe63ca633f66f606 1134ba6f01ef43f49961aa6bbe49f5bc - default default] HTTP exception thrown: Volume 0fc5bec7-9364-458c-a809-f38389890a60 could not be found.
2020-05-13 13:59:07.223 14830 DEBUG nova.api.openstack.wsgi [req-1299524b-1fb1-46b1-82de-9d3ced5c694f c351f9a7674a4a0cbe63ca633f66f606 1134ba6f01ef43f49961aa6bbe49f5bc - default default] Returning 404 to user: Volume 0fc5bec7-9364-458c-a809-f38389890a60 could not be found. __call__ /usr/lib/python2.7/site-packages/nova/api/openstack/wsgi.py:1077
2020-05-13 13:59:07.225 14830 INFO nova.osapi_compute.wsgi.server [req-1299524b-1fb1-46b1-82de-9d3ced5c694f c351f9a7674a4a0cbe63ca633f66f606 1134ba6f01ef43f49961aa6bbe49f5bc - default default] 172.22.0.66,10.176.0.102 "POST /v2.1/servers/c331814d-b758-460e-9972-bc1e987b933d/os-volume_attachments HTTP/1.1" status: 404 len: 506 time: 1.0708430