yahoo-eng-team team mailing list archive

Thread
Date
[Bug 2080427] [NEW] Server status during build occasionally emitted as ERROR from GET /servers/{server_id} when it is not actually in ERROR

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: melanie witt <2080427@xxxxxxxxxxxxxxxxxx>
Date: Wed, 11 Sep 2024 19:40:35 -0000
Reply-to: Bug 2080427 <2080427@xxxxxxxxxxxxxxxxxx>
Sender: noreply@xxxxxxxxxxxxx
Public bug reported:

I have seen this occasionally locally using Devstack and had not been
sure if the behavior was originating from OpenStackClient or Nova
itself.

tl;dr: Instance sometimes gets set to ERROR state temporarily while it
is building. The related nova-compute code is 5 years old, so I don't
know how/why this started happening more recently:
https://github.com/openstack/nova/commit/a1a735bc6efa40d8277c9fc5339f3b74f968b58e

-----

Using --wait in OSC will make the client do a periodic GET of the server
to check the server state and finish waiting once the server goes to
ACTIVE or ERROR. Sometimes it gets an ERROR state from Nova API while
the server is building, but the server does not show as ERROR state when
checked again (and the server is properly running).

Excerpt of --debug output from OSC shows "status": "ERROR" and "OS-EXT-
STS:vm_state": "error" alongside HTTP 200:

boot_args: ['debug', openstack.image.v2.image.Image(hw_rng_model=virtio, name=cirros-0.6.2-x86_64-disk, disk_format=qcow2, container_format=bare, visibility=public, size=21430272, virtual_size=117440512, status=active, checksum=c8fc807773e5354afe61636071771906, protected=False, min_ram=0, min_disk=0, owner=0a93ca5c3cc642e3a5676aa261777422, os_hidden=False, os_hash_algo=sha512, os_hash_value=1103b92ce8ad966e41235a4de260deb791ff571670c0342666c8582fbb9caefe6af07ebb11d34f44f8414b609b29c1bdf1d72ffa6faa39c88e8721d09847952b, id=5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea, created_at=2024-08-01T19:15:43Z, updated_at=2024-08-01T19:15:45Z, tags=[], file=/v2/images/5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea/file, schema=/v2/schemas/image, properties={'owner_specified.openstack.object': 'images/cirros-0.6.2-x86_64-disk', 'owner_specified.openstack.sha256': '', 'owner_specified.openstack.md5': ''}, location=Munch({'cloud': 'devstack', 'region_name': 'RegionOne', 'zone': None, 'project': Munch({'id': '2cee1a9455514ddb909a98d7eda1be50', 'name': 'demo', 'domain_id': 'default', 'domain_name': None})})), <Flavor: m1.tiny.eph.swap>]
boot_kwargs: {'meta': None, 'files': {}, 'reservation_id': None, 'min_count': 1, 'max_count': 1, 'security_groups': [], 'userdata': None, 'key_name': None, 'availability_zone': None, 'admin_pass': None, 'block_device_mapping_v2': [], 'nics': [{'net-id': '02cd8d60-ca53-42ee-bb3a-2ac391bc0760', 'port-id': '', 'v4-fixed-ip': '', 'v6-fixed-ip': ''}], 'scheduler_hints': {}, 'config_drive': None}
REQ: curl -g -i -X POST http://192.168.56.11/compute/v2.1/servers -H "Accept: application/json" -H "Content-Type: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: {SHA256}c214484ad751f8376845d1014e88a36c70a94a8dc5b8ab0eee0eb163fb0ff9f7" -H "X-OpenStack-Nova-API-Version: 2.1" -d '{"server": {"name": "debug", "imageRef": "5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea", "flavorRef": "edb0a3e6-5b83-4566-9be4-8e96a2506853", "min_count": 1, "max_count": 1, "networks": [{"uuid": "02cd8d60-ca53-42ee-bb3a-2ac391bc0760"}]}}'
Resetting dropped connection: 192.168.56.11
http://192.168.56.11:80 "POST /compute/v2.1/servers HTTP/1.1" 202 384
RESP: [202] Connection: close Content-Length: 384 Content-Type: application/json Date: Wed, 11 Sep 2024 18:37:24 GMT OpenStack-API-Version: compute 2.1 Server: Apache/2.4.52 (Ubuntu) Vary: OpenStack-API-Version,X-OpenStack-Nova-API-Version X-OpenStack-Nova-API-Version: 2.1 location: http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c x-compute-request-id: req-11f23d3b-60e4-4813-b6e5-cdff85caa220 x-openstack-request-id: req-11f23d3b-60e4-4813-b6e5-cdff85caa220
RESP BODY: {"server": {"id": "a713413f-cef5-4f32-9b34-b22c915e102c", "links": [{"rel": "self", "href": "http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}, {"rel": "bookmark", "href": "http://192.168.56.11/compute/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}], "OS-DCF:diskConfig": "MANUAL", "security_groups": [{"name": "default"}], "adminPass": "Yi9J68KucWmK"}}
POST call to compute for http://192.168.56.11/compute/v2.1/servers used request id req-11f23d3b-60e4-4813-b6e5-cdff85caa220
REQ: curl -g -i -X GET http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c -H "Accept: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: {SHA256}c214484ad751f8376845d1014e88a36c70a94a8dc5b8ab0eee0eb163fb0ff9f7" -H "X-OpenStack-Nova-API-Version: 2.1"
Resetting dropped connection: 192.168.56.11
http://192.168.56.11:80 "GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c HTTP/1.1" 200 1247
RESP: [200] Connection: close Content-Length: 1247 Content-Type: application/json Date: Wed, 11 Sep 2024 18:37:24 GMT OpenStack-API-Version: compute 2.1 Server: Apache/2.4.52 (Ubuntu) Vary: OpenStack-API-Version,X-OpenStack-Nova-API-Version X-OpenStack-Nova-API-Version: 2.1 x-compute-request-id: req-01964ae7-2bc0-4dfc-81e7-247e17caa840 x-openstack-request-id: req-01964ae7-2bc0-4dfc-81e7-247e17caa840
RESP BODY: {"server": {"id": "a713413f-cef5-4f32-9b34-b22c915e102c", "name": "debug", "status": "BUILD", "tenant_id": "2cee1a9455514ddb909a98d7eda1be50", "user_id": "e384582283d04540b3fa652efd85a913", "metadata": {}, "hostId": "", "image": {"id": "5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea", "links": [{"rel": "bookmark", "href": "http://192.168.56.11/compute/images/5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea"}]}, "flavor": {"id": "edb0a3e6-5b83-4566-9be4-8e96a2506853", "links": [{"rel": "bookmark", "href": "http://192.168.56.11/compute/flavors/edb0a3e6-5b83-4566-9be4-8e96a2506853"}]}, "created": "2024-09-11T18:37:25Z", "updated": "2024-09-11T18:37:24Z", "addresses": {}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}, {"rel": "bookmark", "href": "http://192.168.56.11/compute/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}], "OS-DCF:diskConfig": "MANUAL", "progress": 0, "OS-EXT-AZ:availability_zone": "", "config_drive": "", "key_name": null, "OS-SRV-USG:launched_at": null, "OS-SRV-USG:terminated_at": null, "OS-EXT-STS:task_state": "scheduling", "OS-EXT-STS:vm_state": "building", "OS-EXT-STS:power_state": 0, "os-extended-volumes:volumes_attached": []}}
GET call to compute for http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c used request id req-01964ae7-2bc0-4dfc-81e7-247e17caa840
REQ: curl -g -i -X GET http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c -H "Accept: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: {SHA256}c214484ad751f8376845d1014e88a36c70a94a8dc5b8ab0eee0eb163fb0ff9f7" -H "X-OpenStack-Nova-API-Version: 2.1"
Resetting dropped connection: 192.168.56.11
http://192.168.56.11:80 "GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c HTTP/1.1" 200 1225
RESP: [200] Connection: close Content-Length: 1225 Content-Type: application/json Date: Wed, 11 Sep 2024 18:37:30 GMT OpenStack-API-Version: compute 2.1 Server: Apache/2.4.52 (Ubuntu) Vary: OpenStack-API-Version,X-OpenStack-Nova-API-Version X-OpenStack-Nova-API-Version: 2.1 x-compute-request-id: req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 x-openstack-request-id: req-f37ee7b4-b5a1-45d9-9206-0751de06ff74
RESP BODY: {"server": {"id": "a713413f-cef5-4f32-9b34-b22c915e102c", "name": "debug", "status": "ERROR", "tenant_id": "2cee1a9455514ddb909a98d7eda1be50", "user_id": "e384582283d04540b3fa652efd85a913", "metadata": {}, "hostId": "", "image": {"id": "5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea", "links": [{"rel": "bookmark", "href": "http://192.168.56.11/compute/images/5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea"}]}, "flavor": {"id": "edb0a3e6-5b83-4566-9be4-8e96a2506853", "links": [{"rel": "bookmark", "href": "http://192.168.56.11/compute/flavors/edb0a3e6-5b83-4566-9be4-8e96a2506853"}]}, "created": "2024-09-11T18:37:24Z", "updated": "2024-09-11T18:37:30Z", "addresses": {}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}, {"rel": "bookmark", "href": "http://192.168.56.11/compute/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}], "OS-DCF:diskConfig": "MANUAL", "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "key_name": null, "OS-SRV-USG:launched_at": null, "OS-SRV-USG:terminated_at": null, "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "error", "OS-EXT-STS:power_state": 0, "os-extended-volumes:volumes_attached": []}}
GET call to compute for http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c used request id req-f37ee7b4-b5a1-45d9-9206-0751de06ff74
Error creating server: debug
Traceback (most recent call last):
  File "/opt/stack/data/venv/lib/python3.10/site-packages/cliff/app.py", line 431, in run_subcommand
    result = cmd.run(parsed_args)
  File "/opt/stack/data/venv/lib/python3.10/site-packages/osc_lib/command/command.py", line 38, in run
    return super(Command, self).run(parsed_args)
  File "/opt/stack/data/venv/lib/python3.10/site-packages/cliff/display.py", line 121, in run
    column_names, data = self.take_action(parsed_args)
  File "/opt/stack/data/venv/lib/python3.10/site-packages/openstackclient/compute/v2/server.py", line 2048, in take_action
    raise exceptions.CommandError(msg)
osc_lib.exceptions.CommandError: Error creating server: debug
clean_up CreateServer: Error creating server: debug
END return value: 1


Excerpt of n-api log :

Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.api.openstack.wsgi [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Action: 'create', calling method: <bound method ServersController.create of <nova.api.openstack.compute.servers.ServersController object at 0x7f1df3548460>>, body: {"server": {"name": "debug", "imageRef": "5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea", "flavorRef": "edb0a3e6-5b83-4566-9be4-8e96a2506853", "min_count": 1, "max_count": 1, "networks": [{"uuid": "02cd8d60-ca53-42ee-bb3a-2ac391bc0760"}]}} {{(pid=238141) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:518}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.network.neutron [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] validate_networks() for [('02cd8d60-ca53-42ee-bb3a-2ac391bc0760', None, None, None, None, None)] {{(pid=238141) validate_networks /opt/stack/nova/nova/network/neutron.py:2646}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.virt.hardware [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Flavor limits 0:0:0 {{(pid=238141) get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:348}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.virt.hardware [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Image limits 0:0:0 {{(pid=238141) get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:352}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.virt.hardware [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Flavor pref 0:0:0 {{(pid=238141) get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:388}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.virt.hardware [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Image pref 0:0:0 {{(pid=238141) get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:392}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.virt.hardware [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Chose sockets=0, cores=0, threads=0; limits were sockets=65536, cores=65536, threads=65536 {{(pid=238141) get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:430}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG oslo_concurrency.lockutils [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Acquiring lock "00000000-0000-0000-0000-000000000000" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" {{(pid=238141) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:402}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG oslo_concurrency.lockutils [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Lock "00000000-0000-0000-0000-000000000000" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.001s {{(pid=238141) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:407}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG oslo_concurrency.lockutils [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Lock "00000000-0000-0000-0000-000000000000" "released" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=238141) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:421}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG oslo_concurrency.lockutils [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Acquiring lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" {{(pid=238141) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:402}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG oslo_concurrency.lockutils [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.001s {{(pid=238141) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:407}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG oslo_concurrency.lockutils [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" "released" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=238141) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:421}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.quota [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Getting quotas for project 2cee1a9455514ddb909a98d7eda1be50. Resources: {'instances', 'cores', 'ram'} {{(pid=238141) _get_quotas /opt/stack/nova/nova/quota.py:393}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.quota [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Getting quotas for user e384582283d04540b3fa652efd85a913 and project 2cee1a9455514ddb909a98d7eda1be50. Resources: {'instances', 'cores', 'ram'} {{(pid=238141) _get_quotas /opt/stack/nova/nova/quota.py:383}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.compute.api [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Going to run 1 instances... {{(pid=238141) _provision_instances /opt/stack/nova/nova/compute/api.py:1407}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.compute.api [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] [instance: a713413f-cef5-4f32-9b34-b22c915e102c] block_device_mapping [BlockDeviceMapping(attachment_id=<?>,boot_index=0,connection_info=None,created_at=<?>,delete_on_termination=True,deleted=<?>,deleted_at=<?>,destination_type='local',device_name=None,device_type='disk',disk_bus=None,encrypted=False,encryption_format=None,encryption_options=None,encryption_secret_uuid=None,guest_format=None,id=<?>,image_id='5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea',instance=<?>,instance_uuid=<?>,no_device=False,snapshot_id=None,source_type='image',tag=None,updated_at=<?>,uuid=<?>,volume_id=None,volume_size=None,volume_type=None), BlockDeviceMapping(attachment_id=<?>,boot_index=-1,connection_info=None,created_at=<?>,delete_on_termination=True,deleted=<?>,deleted_at=<?>,destination_type='local',device_name=None,device_type='disk',disk_bus=None,encrypted=False,encryption_format=None,encryption_options=None,encryption_secret_uuid=None,guest_format=None,id=<?>,image_id=None,instance=<?>,instance_uuid=<?>,no_device=False,snapshot_id=None,source_type='blank',tag=None,updated_at=<?>,uuid=<?>,volume_id=None,volume_size=1,volume_type=None), BlockDeviceMapping(attachment_id=<?>,boot_index=-1,connection_info=None,created_at=<?>,delete_on_termination=True,deleted=<?>,deleted_at=<?>,destination_type='local',device_name=None,device_type='disk',disk_bus=None,encrypted=False,encryption_format=None,encryption_options=None,encryption_secret_uuid=None,guest_format='swap',id=<?>,image_id=None,instance=<?>,instance_uuid=<?>,no_device=False,snapshot_id=None,source_type='blank',tag=None,updated_at=<?>,uuid=<?>,volume_id=None,volume_size=512,volume_type=None)] {{(pid=238141) _bdm_validate_set_size_and_instance /opt/stack/nova/nova/compute/api.py:1868}}
Sep 11 18:37:24 controller devstack@n-api.service[238141]: INFO nova.api.openstack.requestlog [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] 192.168.56.11 "POST /compute/v2.1/servers" status: 202 len: 384 microversion: 2.1 time: 0.804829
Sep 11 18:37:24 controller devstack@n-api.service[238141]: [pid: 238141|app: 0|req: 91/272] 192.168.56.11 () {62 vars in 1197 bytes} [Wed Sep 11 18:37:24 2024] POST /compute/v2.1/servers => generated 384 bytes in 807 msecs (HTTP/1.1 202) 10 headers in 453 bytes (1 switches on core 0)
Sep 11 18:37:24 controller devstack@n-api.service[238139]: DEBUG nova.api.openstack.wsgi [None req-01964ae7-2bc0-4dfc-81e7-247e17caa840 demo demo] Calling method '<bound method ServersController.show of <nova.api.openstack.compute.servers.ServersController object at 0x7f1df356f550>>' {{(pid=238139) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:520}}
Sep 11 18:37:24 controller devstack@n-api.service[238139]: DEBUG nova.compute.api [None req-01964ae7-2bc0-4dfc-81e7-247e17caa840 demo demo] [instance: a713413f-cef5-4f32-9b34-b22c915e102c] Fetching instance by UUID {{(pid=238139) get /opt/stack/nova/nova/compute/api.py:2981}}
Sep 11 18:37:24 controller devstack@n-api.service[238139]: DEBUG nova.policy [None req-01964ae7-2bc0-4dfc-81e7-247e17caa840 demo demo] Policy check for os_compute_api:os-extended-server-attributes failed with credentials {'is_admin': False, 'user_id': 'e384582283d04540b3fa652efd85a913', 'user_domain_id': 'default', 'system_scope': None, 'domain_id': None, 'project_id': '2cee1a9455514ddb909a98d7eda1be50', 'project_domain_id': 'default', 'roles': ['member', 'reader', 'anotherrole'], 'is_admin_project': True, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_id': None, 'service_project_domain_id': None, 'service_roles': []} {{(pid=238139) authorize /opt/stack/nova/nova/policy.py:201}}
Sep 11 18:37:24 controller devstack@n-api.service[238139]: INFO nova.api.openstack.requestlog [None req-01964ae7-2bc0-4dfc-81e7-247e17caa840 demo demo] 192.168.56.11 "GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c" status: 200 len: 1247 microversion: 2.1 time: 0.155503
Sep 11 18:37:25 controller devstack@n-api.service[238139]: [pid: 238139|app: 0|req: 92/273] 192.168.56.11 () {58 vars in 1254 bytes} [Wed Sep 11 18:37:24 2024] GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c => generated 1247 bytes in 158 msecs (HTTP/1.1 200) 9 headers in 358 bytes (1 switches on core 0)
Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG nova.api.openstack.wsgi [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Calling method '<bound method ServersController.show of <nova.api.openstack.compute.servers.ServersController object at 0x7f1df3573550>>' {{(pid=238140) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:520}}
Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG nova.compute.api [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] [instance: a713413f-cef5-4f32-9b34-b22c915e102c] Fetching instance by UUID {{(pid=238140) get /opt/stack/nova/nova/compute/api.py:2981}}
Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Acquiring lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:402}}
Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.001s {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:407}}
Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" "released" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:421}}
Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Acquiring lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:402}}
Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.001s {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:407}}
Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" "released" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:421}}
Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Acquiring lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:402}}
Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.001s {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:407}}
Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" "released" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:421}}
Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG nova.objects.instance [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Lazy-loading 'fault' on Instance uuid a713413f-cef5-4f32-9b34-b22c915e102c {{(pid=238140) obj_load_attr /opt/stack/nova/nova/objects/instance.py:1141}}
Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG nova.policy [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Policy check for os_compute_api:os-extended-server-attributes failed with credentials {'is_admin': False, 'user_id': 'e384582283d04540b3fa652efd85a913', 'user_domain_id': 'default', 'system_scope': None, 'domain_id': None, 'project_id': '2cee1a9455514ddb909a98d7eda1be50', 'project_domain_id': 'default', 'roles': ['member', 'reader', 'anotherrole'], 'is_admin_project': True, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_id': None, 'service_project_domain_id': None, 'service_roles': []} {{(pid=238140) authorize /opt/stack/nova/nova/policy.py:201}}
Sep 11 18:37:30 controller devstack@n-api.service[238140]: INFO nova.api.openstack.requestlog [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] 192.168.56.11 "GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c" status: 200 len: 1225 microversion: 2.1 time: 0.143031
Sep 11 18:37:30 controller devstack@n-api.service[238140]: [pid: 238140|app: 0|req: 91/274] 192.168.56.11 () {58 vars in 1254 bytes} [Wed Sep 11 18:37:30 2024] GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c => generated 1225 bytes in 145 msecs (HTTP/1.1 200) 9 headers in 358 bytes (1 switches on core 0)


Excerpt of n-cpu log shows the instance set to ERROR state for "Instance spawn was interrupted before instance_claim, setting instance to ERROR state":

Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.compute.manager [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] [instance: 0c8c97cf-b530-4d13-905f-01793c789d95] Checking state {{(pid=1278209) _get_power_state /opt/stack/nova/nova/compute/manager.py:1791}}
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.compute.manager [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] [instance: 0c8c97cf-b530-4d13-905f-01793c789d95] Current state is 4, state in DB is 4. {{(pid=1278209) _init_instance /opt/stack/nova/nova/compute/manager.py:1313}}
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.compute.manager [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] [instance: 12e78b9c-20e2-4337-8f69-b86f69069d9c] Checking state {{(pid=1278209) _get_power_state /opt/stack/nova/nova/compute/manager.py:1791}}
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.virt.libvirt.vif [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone='nova',cell_name=None,cleaned=False,compute_id=1,config_drive='',created_at=2024-08-15T23:11:26Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=<?>,disable_terminate=False,display_description='ul3',display_name='ul3',ec2_ids=<?>,
ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(6),hidden=False,host='controller',hostname='ul3',id=16,image_ref='5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea',info_cache=InstanceInfoCache,instance_type_id=6,kernel_id='',key_data=None,key_name=None,keypairs=<?>,launch_index=0,launched_at=2024-08-15T23:11:42Z,launched_on='controller',locked=False,locked_by=None,memory_mb=512,metadata={},migration_context=<?>,new_flavor=None,node='controller',numa_topology=None,old_flavor=None,os_type=None,pci_devices=<?>,pci_requests=<?>,power_state=
4,progress=0,project_id='2cee1a9455514ddb909a98d7eda1be50',ramdisk_id='',reservation_id='r-1ewm5mtw',resources=<?>,root_device_name='/dev/vda',root_gb=1,security_groups=<?>,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='reader,member,anotherrole',image_base_image_ref='5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea',image_container_format='bare',image_disk_format='qcow2',image_hw_cdrom_bus='ide',image_hw_disk_bus='virtio',image_hw_input_bus=None,image_hw_machine_type='pc',image_hw_pointer_model=None,image_hw_rng_model='virtio',ima
ge_hw_video_model='virtio',image_hw_vif_model='virtio',image_min_disk='1',image_min_ram='0',image_owner_specified.openstack.md5='',image_owner_specified.openstack.object='images/cirros-0.6.2-x86_64-disk',image_owner_specified.openstack.sha256='',owner_project_name='demo',owner_user_name='demo'},tags=<?>,task_state=None,terminated_at=None,trusted_certs=<?>,updated_at=2024-09-04T16:32:29Z,user_data=None,user_id='e384582283d04540b3fa652efd85a913',uuid=12e78b9c-20e2-4337-8f69-b86f69069d9c,vcpu_model=<?>,vcpus=1,vm_mode=None,vm_state='stopped')
 vif={"id": "5fa2bbd6-59d7-48ca-90d1-8138682c69ac", "address": "fa:16:3e:43:33:11", "network": {"id": "02cd8d60-ca53-42ee-bb3a-2ac391bc0760", "bridge": "br-int", "label": "private", "subnets": [{"cidr": "fd5e:b566:13f0::/64", "dns": [], "gateway": {"address": "fd5e:b566:13f0::1", "type": "gateway", "version": 6, "meta": {}}, "ips": [{"address": "fd5e:b566:13f0:0:f816:3eff:fe43:3311", "type": "fixed", "version": 6, "meta": {}, "floating_ips": []}], "routes": [], "version": 6, "meta": {"enable_dhcp": true, "ipv6_address_mode": "slaac"}}, {"c
idr": "10.0.0.0/26", "dns": [], "gateway": {"address": "10.0.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "10.0.0.36", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"enable_dhcp": true}}], "meta": {"injected": false, "tenant_id": "2cee1a9455514ddb909a98d7eda1be50", "mtu": 1442, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true, "connectivity": "l2", "bridge_name": "br-int", "datapath_type": "system", "bound_drivers"
: {"0": "ovn"}}, "devname": "tap5fa2bbd6-59", "ovs_interfaceid": "5fa2bbd6-59d7-48ca-90d1-8138682c69ac", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "delegate_create": true, "meta": {}} {{(pid=1278209) plug /opt/stack/nova/nova/virt/libvirt/vif.py:719}}
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.network.os_vif_util [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] Converting VIF {"id": "5fa2bbd6-59d7-48ca-90d1-8138682c69ac", "address": "fa:16:3e:43:33:11", "network": {"id": "02cd8d60-ca53-42ee-bb3a-2ac391bc0760", "bridge": "br-int", "label": "private", "subnets": [{"cidr": "fd5e:b566:13f0::/64", "dns": [], "gateway": {"address": "fd5e:b566:13f0::1", "type": "gateway", "version": 6, "meta": {}}, "ips": [{"address": "fd5e:b566:13f0:0:f816:3eff:fe43:3311", "type": "
fixed", "version": 6, "meta": {}, "floating_ips": []}], "routes": [], "version": 6, "meta": {"enable_dhcp": true, "ipv6_address_mode": "slaac"}}, {"cidr": "10.0.0.0/26", "dns": [], "gateway": {"address": "10.0.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "10.0.0.36", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"enable_dhcp": true}}], "meta": {"injected": false, "tenant_id": "2cee1a9455514ddb909a98d7eda1be50", "mtu": 1442, "physical_network": null, "tunnele
d": true}}, "type": "ovs", "details": {"port_filter": true, "connectivity": "l2", "bridge_name": "br-int", "datapath_type": "system", "bound_drivers": {"0": "ovn"}}, "devname": "tap5fa2bbd6-59", "ovs_interfaceid": "5fa2bbd6-59d7-48ca-90d1-8138682c69ac", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "delegate_create": true, "meta": {}} {{(pid=1278209) nova_to_osvif_vif /opt/stack/nova/nova/network/os_vif_util.py:511}}
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.network.os_vif_util [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] Converted object VIFOpenVSwitch(active=False,address=fa:16:3e:43:33:11,bridge_name='br-int',has_traffic_filtering=True,id=5fa2bbd6-59d7-48ca-90d1-8138682c69ac,network=Network(02cd8d60-ca53-42ee-bb3a-2ac391bc0760),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tap5fa2bbd6-59') {{(pid=1278209) nova_to_osvif_vif /opt/stack/nova/nova/network/os_vif_util.py:548}}
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG os_vif [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] Plugging vif VIFOpenVSwitch(active=False,address=fa:16:3e:43:33:11,bridge_name='br-int',has_traffic_filtering=True,id=5fa2bbd6-59d7-48ca-90d1-8138682c69ac,network=Network(02cd8d60-ca53-42ee-bb3a-2ac391bc0760),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tap5fa2bbd6-59') {{(pid=1278209) plug /opt/stack/data/venv/lib/python3.10/site-packages/os_vif/__init__.py:76}}
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG ovsdbapp.backend.ovs_idl.vlog [-] [POLLIN] on fd 16 {{(pid=1278209) __log_wakeup /opt/stack/data/venv/lib/python3.10/site-packages/ovs/poller.py:263}}
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=0): AddBridgeCommand(_result=None, name=br-int, may_exist=True, datapath_type=system) {{(pid=1278209) do_commit /opt/stack/data/venv/lib/python3.10/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:89}}
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Transaction caused no change {{(pid=1278209) do_commit /opt/stack/data/venv/lib/python3.10/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:129}}
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG ovsdbapp.backend.ovs_idl.vlog [-] [POLLIN] on fd 16 {{(pid=1278209) __log_wakeup /opt/stack/data/venv/lib/python3.10/site-packages/ovs/poller.py:263}}
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=0): AddPortCommand(_result=None, bridge=br-int, port=tap5fa2bbd6-59, may_exist=True, interface_attrs={}) {{(pid=1278209) do_commit /opt/stack/data/venv/lib/python3.10/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:89}}
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=1): DbSetCommand(_result=None, table=Interface, record=tap5fa2bbd6-59, col_values=(('external_ids', {'iface-id': '5fa2bbd6-59d7-48ca-90d1-8138682c69ac', 'iface-status': 'active', 'attached-mac': 'fa:16:3e:43:33:11', 'vm-uuid': '12e78b9c-20e2-4337-8f69-b86f69069d9c'}),), if_exists=True) {{(pid=1278209) do_commit /opt/stack/data/venv/lib/python3.10/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:89}}
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Transaction caused no change {{(pid=1278209) do_commit /opt/stack/data/venv/lib/python3.10/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:129}}
Sep 11 18:37:29 controller nova-compute[1278209]: INFO os_vif [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] Successfully plugged vif VIFOpenVSwitch(active=False,address=fa:16:3e:43:33:11,bridge_name='br-int',has_traffic_filtering=True,id=5fa2bbd6-59d7-48ca-90d1-8138682c69ac,network=Network(02cd8d60-ca53-42ee-bb3a-2ac391bc0760),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tap5fa2bbd6-59')
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.compute.manager [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] [instance: 12e78b9c-20e2-4337-8f69-b86f69069d9c] Checking state {{(pid=1278209) _get_power_state /opt/stack/nova/nova/compute/manager.py:1791}}
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.compute.manager [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] [instance: 12e78b9c-20e2-4337-8f69-b86f69069d9c] Current state is 4, state in DB is 4. {{(pid=1278209) _init_instance /opt/stack/nova/nova/compute/manager.py:1313}}
Sep 11 18:37:29 controller nova-compute[1278209]: INFO nova.compute.manager [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] Looking for unclaimed instances stuck in BUILDING status for nodes managed by this host
Sep 11 18:37:29 controller nova-compute[1278209]: INFO oslo_messaging._drivers.amqpdriver [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] Expecting reply to msg 96620f7bac8444aeb6c7e5a26fd831e3 in queue reply_349c97cc777c4301b8b0e9fa67f77959
Sep 11 18:37:29 controller nova-compute[1278209]: INFO oslo_messaging._drivers.amqpdriver [-] Received RPC response for msg 96620f7bac8444aeb6c7e5a26fd831e3
Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.compute.manager [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] [instance: a713413f-cef5-4f32-9b34-b22c915e102c] Instance spawn was interrupted before instance_claim, setting instance to ERROR state {{(pid=1278209) _error_out_instances_whose_build_was_interrupted /opt/stack/nova/nova/compute/manager.py:1748}}


Subsequent 'server show' with --debug does not show any ERROR states:

REQ: curl -g -i -X GET http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c -H "OpenStack-API-Version: compute 2.96" -H "User-Agent: openstacksdk/3.3.0 keystoneauth1/5.7.0 python-requests/2.32.3 CPython/3.10.12" -H "X-Auth-Token: {SHA256}24ab2704d0f91fd353c3b525c11ad62a9eb0b901b5f6d97d6a5acbdf3c55184d" -H "X-OpenStack-Nova-API-Version: 2.96"
Resetting dropped connection: 192.168.56.11
http://192.168.56.11:80 "GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c HTTP/1.1" 200 1789
RESP: [200] Connection: close Content-Length: 1789 Content-Type: application/json Date: Wed, 11 Sep 2024 19:24:50 GMT OpenStack-API-Version: compute 2.96 Server: Apache/2.4.52 (Ubuntu) Vary: OpenStack-API-Version,X-OpenStack-Nova-API-Version X-OpenStack-Nova-API-Version: 2.96 x-compute-request-id: req-6c490990-8b68-43ec-8d4d-14700f079e56 x-openstack-request-id: req-6c490990-8b68-43ec-8d4d-14700f079e56
RESP BODY: {"server": {"id": "a713413f-cef5-4f32-9b34-b22c915e102c", "name": "debug", "status": "ACTIVE", "tenant_id": "2cee1a9455514ddb909a98d7eda1be50", "user_id": "e384582283d04540b3fa652efd85a913", "metadata": {}, "hostId": "075d4fd268d13c993ed6e9eb84ad44f016beff74f0cf7876aa471b05", "image": {"id": "5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea", "links": [{"rel": "bookmark", "href": "http://192.168.56.11/compute/images/5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea"}]}, "flavor": {"vcpus": 1, "ram": 512, "disk": 1, "ephemeral": 1, "swap": 512, "original_name": "m1.tiny.eph.swap", "extra_specs": {}}, "created": "2024-09-11T18:37:24Z", "updated": "2024-09-11T18:37:59Z", "addresses": {"private": [{"version": 6, "addr": "fd5e:b566:13f0:0:f816:3eff:fe45:c462", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:45:c4:62"}, {"version": 4, "addr": "10.0.0.21", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:45:c4:62"}]}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}, {"rel": "bookmark", "href": "http://192.168.56.11/compute/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}], "OS-DCF:diskConfig": "MANUAL", "progress": 0, "OS-EXT-AZ:availability_zone": "nova", "pinned_availability_zone": null, "config_drive": "", "key_name": null, "OS-SRV-USG:launched_at": "2024-09-11T18:37:58.000000", "OS-SRV-USG:terminated_at": null, "security_groups": [{"name": "default"}], "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "active", "OS-EXT-STS:power_state": 1, "os-extended-volumes:volumes_attached": [], "locked": false, "locked_reason": null, "description": "debug", "tags": [], "trusted_image_certificates": null, "OS-EXT-SRV-ATTR:hostname": "debug", "server_groups": []}}
GET call to compute for http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c used request id req-6c490990-8b68-43ec-8d4d-14700f079e56
REQ: curl -g -i -X GET http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c -H "OpenStack-API-Version: compute 2.96" -H "User-Agent: openstacksdk/3.3.0 keystoneauth1/5.7.0 python-requests/2.32.3 CPython/3.10.12" -H "X-Auth-Token: {SHA256}24ab2704d0f91fd353c3b525c11ad62a9eb0b901b5f6d97d6a5acbdf3c55184d" -H "X-OpenStack-Nova-API-Version: 2.96"
Resetting dropped connection: 192.168.56.11
http://192.168.56.11:80 "GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c HTTP/1.1" 200 1789
RESP: [200] Connection: close Content-Length: 1789 Content-Type: application/json Date: Wed, 11 Sep 2024 19:24:51 GMT OpenStack-API-Version: compute 2.96 Server: Apache/2.4.52 (Ubuntu) Vary: OpenStack-API-Version,X-OpenStack-Nova-API-Version X-OpenStack-Nova-API-Version: 2.96 x-compute-request-id: req-bb0029e7-d6d5-49c1-a06e-7bcfac66f016 x-openstack-request-id: req-bb0029e7-d6d5-49c1-a06e-7bcfac66f016
RESP BODY: {"server": {"id": "a713413f-cef5-4f32-9b34-b22c915e102c", "name": "debug", "status": "ACTIVE", "tenant_id": "2cee1a9455514ddb909a98d7eda1be50", "user_id": "e384582283d04540b3fa652efd85a913", "metadata": {}, "hostId": "075d4fd268d13c993ed6e9eb84ad44f016beff74f0cf7876aa471b05", "image": {"id": "5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea", "links": [{"rel": "bookmark", "href": "http://192.168.56.11/compute/images/5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea"}]}, "flavor": {"vcpus": 1, "ram": 512, "disk": 1, "ephemeral": 1, "swap": 512, "original_name": "m1.tiny.eph.swap", "extra_specs": {}}, "created": "2024-09-11T18:37:24Z", "updated": "2024-09-11T18:37:59Z", "addresses": {"private": [{"version": 6, "addr": "fd5e:b566:13f0:0:f816:3eff:fe45:c462", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:45:c4:62"}, {"version": 4, "addr": "10.0.0.21", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:45:c4:62"}]}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}, {"rel": "bookmark", "href": "http://192.168.56.11/compute/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}], "OS-DCF:diskConfig": "MANUAL", "progress": 0, "OS-EXT-AZ:availability_zone": "nova", "pinned_availability_zone": null, "config_drive": "", "key_name": null, "OS-SRV-USG:launched_at": "2024-09-11T18:37:58.000000", "OS-SRV-USG:terminated_at": null, "security_groups": [{"name": "default"}], "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "active", "OS-EXT-STS:power_state": 1, "os-extended-volumes:volumes_attached": [], "locked": false, "locked_reason": null, "description": "debug", "tags": [], "trusted_image_certificates": null, "OS-EXT-SRV-ATTR:hostname": "debug", "server_groups": []}}
GET call to compute for http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c used request id req-bb0029e7-d6d5-49c1-a06e-7bcfac66f016

** Affects: nova
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/2080427

Title:
  Server status during build occasionally emitted as ERROR from GET
  /servers/{server_id} when it is not actually in ERROR

Status in OpenStack Compute (nova):
  New

Bug description:
  I have seen this occasionally locally using Devstack and had not been
  sure if the behavior was originating from OpenStackClient or Nova
  itself.

  tl;dr: Instance sometimes gets set to ERROR state temporarily while it
  is building. The related nova-compute code is 5 years old, so I don't
  know how/why this started happening more recently:
  https://github.com/openstack/nova/commit/a1a735bc6efa40d8277c9fc5339f3b74f968b58e

  -----

  Using --wait in OSC will make the client do a periodic GET of the
  server to check the server state and finish waiting once the server
  goes to ACTIVE or ERROR. Sometimes it gets an ERROR state from Nova
  API while the server is building, but the server does not show as
  ERROR state when checked again (and the server is properly running).

  Excerpt of --debug output from OSC shows "status": "ERROR" and "OS-
  EXT-STS:vm_state": "error" alongside HTTP 200:

  boot_args: ['debug', openstack.image.v2.image.Image(hw_rng_model=virtio, name=cirros-0.6.2-x86_64-disk, disk_format=qcow2, container_format=bare, visibility=public, size=21430272, virtual_size=117440512, status=active, checksum=c8fc807773e5354afe61636071771906, protected=False, min_ram=0, min_disk=0, owner=0a93ca5c3cc642e3a5676aa261777422, os_hidden=False, os_hash_algo=sha512, os_hash_value=1103b92ce8ad966e41235a4de260deb791ff571670c0342666c8582fbb9caefe6af07ebb11d34f44f8414b609b29c1bdf1d72ffa6faa39c88e8721d09847952b, id=5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea, created_at=2024-08-01T19:15:43Z, updated_at=2024-08-01T19:15:45Z, tags=[], file=/v2/images/5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea/file, schema=/v2/schemas/image, properties={'owner_specified.openstack.object': 'images/cirros-0.6.2-x86_64-disk', 'owner_specified.openstack.sha256': '', 'owner_specified.openstack.md5': ''}, location=Munch({'cloud': 'devstack', 'region_name': 'RegionOne', 'zone': None, 'project': Munch({'id': '2cee1a9455514ddb909a98d7eda1be50', 'name': 'demo', 'domain_id': 'default', 'domain_name': None})})), <Flavor: m1.tiny.eph.swap>]
  boot_kwargs: {'meta': None, 'files': {}, 'reservation_id': None, 'min_count': 1, 'max_count': 1, 'security_groups': [], 'userdata': None, 'key_name': None, 'availability_zone': None, 'admin_pass': None, 'block_device_mapping_v2': [], 'nics': [{'net-id': '02cd8d60-ca53-42ee-bb3a-2ac391bc0760', 'port-id': '', 'v4-fixed-ip': '', 'v6-fixed-ip': ''}], 'scheduler_hints': {}, 'config_drive': None}
  REQ: curl -g -i -X POST http://192.168.56.11/compute/v2.1/servers -H "Accept: application/json" -H "Content-Type: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: {SHA256}c214484ad751f8376845d1014e88a36c70a94a8dc5b8ab0eee0eb163fb0ff9f7" -H "X-OpenStack-Nova-API-Version: 2.1" -d '{"server": {"name": "debug", "imageRef": "5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea", "flavorRef": "edb0a3e6-5b83-4566-9be4-8e96a2506853", "min_count": 1, "max_count": 1, "networks": [{"uuid": "02cd8d60-ca53-42ee-bb3a-2ac391bc0760"}]}}'
  Resetting dropped connection: 192.168.56.11
  http://192.168.56.11:80 "POST /compute/v2.1/servers HTTP/1.1" 202 384
  RESP: [202] Connection: close Content-Length: 384 Content-Type: application/json Date: Wed, 11 Sep 2024 18:37:24 GMT OpenStack-API-Version: compute 2.1 Server: Apache/2.4.52 (Ubuntu) Vary: OpenStack-API-Version,X-OpenStack-Nova-API-Version X-OpenStack-Nova-API-Version: 2.1 location: http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c x-compute-request-id: req-11f23d3b-60e4-4813-b6e5-cdff85caa220 x-openstack-request-id: req-11f23d3b-60e4-4813-b6e5-cdff85caa220
  RESP BODY: {"server": {"id": "a713413f-cef5-4f32-9b34-b22c915e102c", "links": [{"rel": "self", "href": "http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}, {"rel": "bookmark", "href": "http://192.168.56.11/compute/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}], "OS-DCF:diskConfig": "MANUAL", "security_groups": [{"name": "default"}], "adminPass": "Yi9J68KucWmK"}}
  POST call to compute for http://192.168.56.11/compute/v2.1/servers used request id req-11f23d3b-60e4-4813-b6e5-cdff85caa220
  REQ: curl -g -i -X GET http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c -H "Accept: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: {SHA256}c214484ad751f8376845d1014e88a36c70a94a8dc5b8ab0eee0eb163fb0ff9f7" -H "X-OpenStack-Nova-API-Version: 2.1"
  Resetting dropped connection: 192.168.56.11
  http://192.168.56.11:80 "GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c HTTP/1.1" 200 1247
  RESP: [200] Connection: close Content-Length: 1247 Content-Type: application/json Date: Wed, 11 Sep 2024 18:37:24 GMT OpenStack-API-Version: compute 2.1 Server: Apache/2.4.52 (Ubuntu) Vary: OpenStack-API-Version,X-OpenStack-Nova-API-Version X-OpenStack-Nova-API-Version: 2.1 x-compute-request-id: req-01964ae7-2bc0-4dfc-81e7-247e17caa840 x-openstack-request-id: req-01964ae7-2bc0-4dfc-81e7-247e17caa840
  RESP BODY: {"server": {"id": "a713413f-cef5-4f32-9b34-b22c915e102c", "name": "debug", "status": "BUILD", "tenant_id": "2cee1a9455514ddb909a98d7eda1be50", "user_id": "e384582283d04540b3fa652efd85a913", "metadata": {}, "hostId": "", "image": {"id": "5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea", "links": [{"rel": "bookmark", "href": "http://192.168.56.11/compute/images/5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea"}]}, "flavor": {"id": "edb0a3e6-5b83-4566-9be4-8e96a2506853", "links": [{"rel": "bookmark", "href": "http://192.168.56.11/compute/flavors/edb0a3e6-5b83-4566-9be4-8e96a2506853"}]}, "created": "2024-09-11T18:37:25Z", "updated": "2024-09-11T18:37:24Z", "addresses": {}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}, {"rel": "bookmark", "href": "http://192.168.56.11/compute/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}], "OS-DCF:diskConfig": "MANUAL", "progress": 0, "OS-EXT-AZ:availability_zone": "", "config_drive": "", "key_name": null, "OS-SRV-USG:launched_at": null, "OS-SRV-USG:terminated_at": null, "OS-EXT-STS:task_state": "scheduling", "OS-EXT-STS:vm_state": "building", "OS-EXT-STS:power_state": 0, "os-extended-volumes:volumes_attached": []}}
  GET call to compute for http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c used request id req-01964ae7-2bc0-4dfc-81e7-247e17caa840
  REQ: curl -g -i -X GET http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c -H "Accept: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: {SHA256}c214484ad751f8376845d1014e88a36c70a94a8dc5b8ab0eee0eb163fb0ff9f7" -H "X-OpenStack-Nova-API-Version: 2.1"
  Resetting dropped connection: 192.168.56.11
  http://192.168.56.11:80 "GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c HTTP/1.1" 200 1225
  RESP: [200] Connection: close Content-Length: 1225 Content-Type: application/json Date: Wed, 11 Sep 2024 18:37:30 GMT OpenStack-API-Version: compute 2.1 Server: Apache/2.4.52 (Ubuntu) Vary: OpenStack-API-Version,X-OpenStack-Nova-API-Version X-OpenStack-Nova-API-Version: 2.1 x-compute-request-id: req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 x-openstack-request-id: req-f37ee7b4-b5a1-45d9-9206-0751de06ff74
  RESP BODY: {"server": {"id": "a713413f-cef5-4f32-9b34-b22c915e102c", "name": "debug", "status": "ERROR", "tenant_id": "2cee1a9455514ddb909a98d7eda1be50", "user_id": "e384582283d04540b3fa652efd85a913", "metadata": {}, "hostId": "", "image": {"id": "5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea", "links": [{"rel": "bookmark", "href": "http://192.168.56.11/compute/images/5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea"}]}, "flavor": {"id": "edb0a3e6-5b83-4566-9be4-8e96a2506853", "links": [{"rel": "bookmark", "href": "http://192.168.56.11/compute/flavors/edb0a3e6-5b83-4566-9be4-8e96a2506853"}]}, "created": "2024-09-11T18:37:24Z", "updated": "2024-09-11T18:37:30Z", "addresses": {}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}, {"rel": "bookmark", "href": "http://192.168.56.11/compute/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}], "OS-DCF:diskConfig": "MANUAL", "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "key_name": null, "OS-SRV-USG:launched_at": null, "OS-SRV-USG:terminated_at": null, "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "error", "OS-EXT-STS:power_state": 0, "os-extended-volumes:volumes_attached": []}}
  GET call to compute for http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c used request id req-f37ee7b4-b5a1-45d9-9206-0751de06ff74
  Error creating server: debug
  Traceback (most recent call last):
    File "/opt/stack/data/venv/lib/python3.10/site-packages/cliff/app.py", line 431, in run_subcommand
      result = cmd.run(parsed_args)
    File "/opt/stack/data/venv/lib/python3.10/site-packages/osc_lib/command/command.py", line 38, in run
      return super(Command, self).run(parsed_args)
    File "/opt/stack/data/venv/lib/python3.10/site-packages/cliff/display.py", line 121, in run
      column_names, data = self.take_action(parsed_args)
    File "/opt/stack/data/venv/lib/python3.10/site-packages/openstackclient/compute/v2/server.py", line 2048, in take_action
      raise exceptions.CommandError(msg)
  osc_lib.exceptions.CommandError: Error creating server: debug
  clean_up CreateServer: Error creating server: debug
  END return value: 1

  
  Excerpt of n-api log :

  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.api.openstack.wsgi [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Action: 'create', calling method: <bound method ServersController.create of <nova.api.openstack.compute.servers.ServersController object at 0x7f1df3548460>>, body: {"server": {"name": "debug", "imageRef": "5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea", "flavorRef": "edb0a3e6-5b83-4566-9be4-8e96a2506853", "min_count": 1, "max_count": 1, "networks": [{"uuid": "02cd8d60-ca53-42ee-bb3a-2ac391bc0760"}]}} {{(pid=238141) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:518}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.network.neutron [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] validate_networks() for [('02cd8d60-ca53-42ee-bb3a-2ac391bc0760', None, None, None, None, None)] {{(pid=238141) validate_networks /opt/stack/nova/nova/network/neutron.py:2646}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.virt.hardware [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Flavor limits 0:0:0 {{(pid=238141) get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:348}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.virt.hardware [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Image limits 0:0:0 {{(pid=238141) get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:352}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.virt.hardware [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Flavor pref 0:0:0 {{(pid=238141) get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:388}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.virt.hardware [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Image pref 0:0:0 {{(pid=238141) get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:392}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.virt.hardware [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Chose sockets=0, cores=0, threads=0; limits were sockets=65536, cores=65536, threads=65536 {{(pid=238141) get_cpu_topology_constraints /opt/stack/nova/nova/virt/hardware.py:430}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG oslo_concurrency.lockutils [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Acquiring lock "00000000-0000-0000-0000-000000000000" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" {{(pid=238141) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:402}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG oslo_concurrency.lockutils [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Lock "00000000-0000-0000-0000-000000000000" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.001s {{(pid=238141) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:407}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG oslo_concurrency.lockutils [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Lock "00000000-0000-0000-0000-000000000000" "released" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=238141) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:421}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG oslo_concurrency.lockutils [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Acquiring lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" {{(pid=238141) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:402}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG oslo_concurrency.lockutils [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.001s {{(pid=238141) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:407}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG oslo_concurrency.lockutils [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" "released" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=238141) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:421}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.quota [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Getting quotas for project 2cee1a9455514ddb909a98d7eda1be50. Resources: {'instances', 'cores', 'ram'} {{(pid=238141) _get_quotas /opt/stack/nova/nova/quota.py:393}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.quota [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Getting quotas for user e384582283d04540b3fa652efd85a913 and project 2cee1a9455514ddb909a98d7eda1be50. Resources: {'instances', 'cores', 'ram'} {{(pid=238141) _get_quotas /opt/stack/nova/nova/quota.py:383}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.compute.api [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] Going to run 1 instances... {{(pid=238141) _provision_instances /opt/stack/nova/nova/compute/api.py:1407}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: DEBUG nova.compute.api [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] [instance: a713413f-cef5-4f32-9b34-b22c915e102c] block_device_mapping [BlockDeviceMapping(attachment_id=<?>,boot_index=0,connection_info=None,created_at=<?>,delete_on_termination=True,deleted=<?>,deleted_at=<?>,destination_type='local',device_name=None,device_type='disk',disk_bus=None,encrypted=False,encryption_format=None,encryption_options=None,encryption_secret_uuid=None,guest_format=None,id=<?>,image_id='5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea',instance=<?>,instance_uuid=<?>,no_device=False,snapshot_id=None,source_type='image',tag=None,updated_at=<?>,uuid=<?>,volume_id=None,volume_size=None,volume_type=None), BlockDeviceMapping(attachment_id=<?>,boot_index=-1,connection_info=None,created_at=<?>,delete_on_termination=True,deleted=<?>,deleted_at=<?>,destination_type='local',device_name=None,device_type='disk',disk_bus=None,encrypted=False,encryption_format=None,encryption_options=None,encryption_secret_uuid=None,guest_format=None,id=<?>,image_id=None,instance=<?>,instance_uuid=<?>,no_device=False,snapshot_id=None,source_type='blank',tag=None,updated_at=<?>,uuid=<?>,volume_id=None,volume_size=1,volume_type=None), BlockDeviceMapping(attachment_id=<?>,boot_index=-1,connection_info=None,created_at=<?>,delete_on_termination=True,deleted=<?>,deleted_at=<?>,destination_type='local',device_name=None,device_type='disk',disk_bus=None,encrypted=False,encryption_format=None,encryption_options=None,encryption_secret_uuid=None,guest_format='swap',id=<?>,image_id=None,instance=<?>,instance_uuid=<?>,no_device=False,snapshot_id=None,source_type='blank',tag=None,updated_at=<?>,uuid=<?>,volume_id=None,volume_size=512,volume_type=None)] {{(pid=238141) _bdm_validate_set_size_and_instance /opt/stack/nova/nova/compute/api.py:1868}}
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: INFO nova.api.openstack.requestlog [None req-11f23d3b-60e4-4813-b6e5-cdff85caa220 demo demo] 192.168.56.11 "POST /compute/v2.1/servers" status: 202 len: 384 microversion: 2.1 time: 0.804829
  Sep 11 18:37:24 controller devstack@n-api.service[238141]: [pid: 238141|app: 0|req: 91/272] 192.168.56.11 () {62 vars in 1197 bytes} [Wed Sep 11 18:37:24 2024] POST /compute/v2.1/servers => generated 384 bytes in 807 msecs (HTTP/1.1 202) 10 headers in 453 bytes (1 switches on core 0)
  Sep 11 18:37:24 controller devstack@n-api.service[238139]: DEBUG nova.api.openstack.wsgi [None req-01964ae7-2bc0-4dfc-81e7-247e17caa840 demo demo] Calling method '<bound method ServersController.show of <nova.api.openstack.compute.servers.ServersController object at 0x7f1df356f550>>' {{(pid=238139) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:520}}
  Sep 11 18:37:24 controller devstack@n-api.service[238139]: DEBUG nova.compute.api [None req-01964ae7-2bc0-4dfc-81e7-247e17caa840 demo demo] [instance: a713413f-cef5-4f32-9b34-b22c915e102c] Fetching instance by UUID {{(pid=238139) get /opt/stack/nova/nova/compute/api.py:2981}}
  Sep 11 18:37:24 controller devstack@n-api.service[238139]: DEBUG nova.policy [None req-01964ae7-2bc0-4dfc-81e7-247e17caa840 demo demo] Policy check for os_compute_api:os-extended-server-attributes failed with credentials {'is_admin': False, 'user_id': 'e384582283d04540b3fa652efd85a913', 'user_domain_id': 'default', 'system_scope': None, 'domain_id': None, 'project_id': '2cee1a9455514ddb909a98d7eda1be50', 'project_domain_id': 'default', 'roles': ['member', 'reader', 'anotherrole'], 'is_admin_project': True, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_id': None, 'service_project_domain_id': None, 'service_roles': []} {{(pid=238139) authorize /opt/stack/nova/nova/policy.py:201}}
  Sep 11 18:37:24 controller devstack@n-api.service[238139]: INFO nova.api.openstack.requestlog [None req-01964ae7-2bc0-4dfc-81e7-247e17caa840 demo demo] 192.168.56.11 "GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c" status: 200 len: 1247 microversion: 2.1 time: 0.155503
  Sep 11 18:37:25 controller devstack@n-api.service[238139]: [pid: 238139|app: 0|req: 92/273] 192.168.56.11 () {58 vars in 1254 bytes} [Wed Sep 11 18:37:24 2024] GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c => generated 1247 bytes in 158 msecs (HTTP/1.1 200) 9 headers in 358 bytes (1 switches on core 0)
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG nova.api.openstack.wsgi [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Calling method '<bound method ServersController.show of <nova.api.openstack.compute.servers.ServersController object at 0x7f1df3573550>>' {{(pid=238140) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:520}}
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG nova.compute.api [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] [instance: a713413f-cef5-4f32-9b34-b22c915e102c] Fetching instance by UUID {{(pid=238140) get /opt/stack/nova/nova/compute/api.py:2981}}
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Acquiring lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:402}}
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.001s {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:407}}
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" "released" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:421}}
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Acquiring lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:402}}
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.001s {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:407}}
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" "released" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:421}}
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Acquiring lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:402}}
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.001s {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:407}}
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG oslo_concurrency.lockutils [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Lock "0b9dfb2b-4b1a-44c5-81c0-62b99a7943e0" "released" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=238140) inner /opt/stack/data/venv/lib/python3.10/site-packages/oslo_concurrency/lockutils.py:421}}
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG nova.objects.instance [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Lazy-loading 'fault' on Instance uuid a713413f-cef5-4f32-9b34-b22c915e102c {{(pid=238140) obj_load_attr /opt/stack/nova/nova/objects/instance.py:1141}}
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: DEBUG nova.policy [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] Policy check for os_compute_api:os-extended-server-attributes failed with credentials {'is_admin': False, 'user_id': 'e384582283d04540b3fa652efd85a913', 'user_domain_id': 'default', 'system_scope': None, 'domain_id': None, 'project_id': '2cee1a9455514ddb909a98d7eda1be50', 'project_domain_id': 'default', 'roles': ['member', 'reader', 'anotherrole'], 'is_admin_project': True, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_id': None, 'service_project_domain_id': None, 'service_roles': []} {{(pid=238140) authorize /opt/stack/nova/nova/policy.py:201}}
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: INFO nova.api.openstack.requestlog [None req-f37ee7b4-b5a1-45d9-9206-0751de06ff74 demo demo] 192.168.56.11 "GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c" status: 200 len: 1225 microversion: 2.1 time: 0.143031
  Sep 11 18:37:30 controller devstack@n-api.service[238140]: [pid: 238140|app: 0|req: 91/274] 192.168.56.11 () {58 vars in 1254 bytes} [Wed Sep 11 18:37:30 2024] GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c => generated 1225 bytes in 145 msecs (HTTP/1.1 200) 9 headers in 358 bytes (1 switches on core 0)

  
  Excerpt of n-cpu log shows the instance set to ERROR state for "Instance spawn was interrupted before instance_claim, setting instance to ERROR state":

  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.compute.manager [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] [instance: 0c8c97cf-b530-4d13-905f-01793c789d95] Checking state {{(pid=1278209) _get_power_state /opt/stack/nova/nova/compute/manager.py:1791}}
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.compute.manager [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] [instance: 0c8c97cf-b530-4d13-905f-01793c789d95] Current state is 4, state in DB is 4. {{(pid=1278209) _init_instance /opt/stack/nova/nova/compute/manager.py:1313}}
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.compute.manager [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] [instance: 12e78b9c-20e2-4337-8f69-b86f69069d9c] Checking state {{(pid=1278209) _get_power_state /opt/stack/nova/nova/compute/manager.py:1791}}
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.virt.libvirt.vif [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone='nova',cell_name=None,cleaned=False,compute_id=1,config_drive='',created_at=2024-08-15T23:11:26Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=<?>,disable_terminate=False,display_description='ul3',display_name='ul3',ec2_ids=<?>,
  ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(6),hidden=False,host='controller',hostname='ul3',id=16,image_ref='5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea',info_cache=InstanceInfoCache,instance_type_id=6,kernel_id='',key_data=None,key_name=None,keypairs=<?>,launch_index=0,launched_at=2024-08-15T23:11:42Z,launched_on='controller',locked=False,locked_by=None,memory_mb=512,metadata={},migration_context=<?>,new_flavor=None,node='controller',numa_topology=None,old_flavor=None,os_type=None,pci_devices=<?>,pci_requests=<?>,power_state=
  4,progress=0,project_id='2cee1a9455514ddb909a98d7eda1be50',ramdisk_id='',reservation_id='r-1ewm5mtw',resources=<?>,root_device_name='/dev/vda',root_gb=1,security_groups=<?>,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='reader,member,anotherrole',image_base_image_ref='5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea',image_container_format='bare',image_disk_format='qcow2',image_hw_cdrom_bus='ide',image_hw_disk_bus='virtio',image_hw_input_bus=None,image_hw_machine_type='pc',image_hw_pointer_model=None,image_hw_rng_model='virtio',ima
  ge_hw_video_model='virtio',image_hw_vif_model='virtio',image_min_disk='1',image_min_ram='0',image_owner_specified.openstack.md5='',image_owner_specified.openstack.object='images/cirros-0.6.2-x86_64-disk',image_owner_specified.openstack.sha256='',owner_project_name='demo',owner_user_name='demo'},tags=<?>,task_state=None,terminated_at=None,trusted_certs=<?>,updated_at=2024-09-04T16:32:29Z,user_data=None,user_id='e384582283d04540b3fa652efd85a913',uuid=12e78b9c-20e2-4337-8f69-b86f69069d9c,vcpu_model=<?>,vcpus=1,vm_mode=None,vm_state='stopped')
   vif={"id": "5fa2bbd6-59d7-48ca-90d1-8138682c69ac", "address": "fa:16:3e:43:33:11", "network": {"id": "02cd8d60-ca53-42ee-bb3a-2ac391bc0760", "bridge": "br-int", "label": "private", "subnets": [{"cidr": "fd5e:b566:13f0::/64", "dns": [], "gateway": {"address": "fd5e:b566:13f0::1", "type": "gateway", "version": 6, "meta": {}}, "ips": [{"address": "fd5e:b566:13f0:0:f816:3eff:fe43:3311", "type": "fixed", "version": 6, "meta": {}, "floating_ips": []}], "routes": [], "version": 6, "meta": {"enable_dhcp": true, "ipv6_address_mode": "slaac"}}, {"c
  idr": "10.0.0.0/26", "dns": [], "gateway": {"address": "10.0.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "10.0.0.36", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"enable_dhcp": true}}], "meta": {"injected": false, "tenant_id": "2cee1a9455514ddb909a98d7eda1be50", "mtu": 1442, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true, "connectivity": "l2", "bridge_name": "br-int", "datapath_type": "system", "bound_drivers"
  : {"0": "ovn"}}, "devname": "tap5fa2bbd6-59", "ovs_interfaceid": "5fa2bbd6-59d7-48ca-90d1-8138682c69ac", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "delegate_create": true, "meta": {}} {{(pid=1278209) plug /opt/stack/nova/nova/virt/libvirt/vif.py:719}}
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.network.os_vif_util [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] Converting VIF {"id": "5fa2bbd6-59d7-48ca-90d1-8138682c69ac", "address": "fa:16:3e:43:33:11", "network": {"id": "02cd8d60-ca53-42ee-bb3a-2ac391bc0760", "bridge": "br-int", "label": "private", "subnets": [{"cidr": "fd5e:b566:13f0::/64", "dns": [], "gateway": {"address": "fd5e:b566:13f0::1", "type": "gateway", "version": 6, "meta": {}}, "ips": [{"address": "fd5e:b566:13f0:0:f816:3eff:fe43:3311", "type": "
  fixed", "version": 6, "meta": {}, "floating_ips": []}], "routes": [], "version": 6, "meta": {"enable_dhcp": true, "ipv6_address_mode": "slaac"}}, {"cidr": "10.0.0.0/26", "dns": [], "gateway": {"address": "10.0.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "10.0.0.36", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"enable_dhcp": true}}], "meta": {"injected": false, "tenant_id": "2cee1a9455514ddb909a98d7eda1be50", "mtu": 1442, "physical_network": null, "tunnele
  d": true}}, "type": "ovs", "details": {"port_filter": true, "connectivity": "l2", "bridge_name": "br-int", "datapath_type": "system", "bound_drivers": {"0": "ovn"}}, "devname": "tap5fa2bbd6-59", "ovs_interfaceid": "5fa2bbd6-59d7-48ca-90d1-8138682c69ac", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "delegate_create": true, "meta": {}} {{(pid=1278209) nova_to_osvif_vif /opt/stack/nova/nova/network/os_vif_util.py:511}}
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.network.os_vif_util [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] Converted object VIFOpenVSwitch(active=False,address=fa:16:3e:43:33:11,bridge_name='br-int',has_traffic_filtering=True,id=5fa2bbd6-59d7-48ca-90d1-8138682c69ac,network=Network(02cd8d60-ca53-42ee-bb3a-2ac391bc0760),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tap5fa2bbd6-59') {{(pid=1278209) nova_to_osvif_vif /opt/stack/nova/nova/network/os_vif_util.py:548}}
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG os_vif [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] Plugging vif VIFOpenVSwitch(active=False,address=fa:16:3e:43:33:11,bridge_name='br-int',has_traffic_filtering=True,id=5fa2bbd6-59d7-48ca-90d1-8138682c69ac,network=Network(02cd8d60-ca53-42ee-bb3a-2ac391bc0760),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tap5fa2bbd6-59') {{(pid=1278209) plug /opt/stack/data/venv/lib/python3.10/site-packages/os_vif/__init__.py:76}}
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG ovsdbapp.backend.ovs_idl.vlog [-] [POLLIN] on fd 16 {{(pid=1278209) __log_wakeup /opt/stack/data/venv/lib/python3.10/site-packages/ovs/poller.py:263}}
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=0): AddBridgeCommand(_result=None, name=br-int, may_exist=True, datapath_type=system) {{(pid=1278209) do_commit /opt/stack/data/venv/lib/python3.10/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:89}}
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Transaction caused no change {{(pid=1278209) do_commit /opt/stack/data/venv/lib/python3.10/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:129}}
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG ovsdbapp.backend.ovs_idl.vlog [-] [POLLIN] on fd 16 {{(pid=1278209) __log_wakeup /opt/stack/data/venv/lib/python3.10/site-packages/ovs/poller.py:263}}
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=0): AddPortCommand(_result=None, bridge=br-int, port=tap5fa2bbd6-59, may_exist=True, interface_attrs={}) {{(pid=1278209) do_commit /opt/stack/data/venv/lib/python3.10/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:89}}
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=1): DbSetCommand(_result=None, table=Interface, record=tap5fa2bbd6-59, col_values=(('external_ids', {'iface-id': '5fa2bbd6-59d7-48ca-90d1-8138682c69ac', 'iface-status': 'active', 'attached-mac': 'fa:16:3e:43:33:11', 'vm-uuid': '12e78b9c-20e2-4337-8f69-b86f69069d9c'}),), if_exists=True) {{(pid=1278209) do_commit /opt/stack/data/venv/lib/python3.10/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:89}}
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Transaction caused no change {{(pid=1278209) do_commit /opt/stack/data/venv/lib/python3.10/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:129}}
  Sep 11 18:37:29 controller nova-compute[1278209]: INFO os_vif [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] Successfully plugged vif VIFOpenVSwitch(active=False,address=fa:16:3e:43:33:11,bridge_name='br-int',has_traffic_filtering=True,id=5fa2bbd6-59d7-48ca-90d1-8138682c69ac,network=Network(02cd8d60-ca53-42ee-bb3a-2ac391bc0760),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tap5fa2bbd6-59')
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.compute.manager [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] [instance: 12e78b9c-20e2-4337-8f69-b86f69069d9c] Checking state {{(pid=1278209) _get_power_state /opt/stack/nova/nova/compute/manager.py:1791}}
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.compute.manager [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] [instance: 12e78b9c-20e2-4337-8f69-b86f69069d9c] Current state is 4, state in DB is 4. {{(pid=1278209) _init_instance /opt/stack/nova/nova/compute/manager.py:1313}}
  Sep 11 18:37:29 controller nova-compute[1278209]: INFO nova.compute.manager [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] Looking for unclaimed instances stuck in BUILDING status for nodes managed by this host
  Sep 11 18:37:29 controller nova-compute[1278209]: INFO oslo_messaging._drivers.amqpdriver [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] Expecting reply to msg 96620f7bac8444aeb6c7e5a26fd831e3 in queue reply_349c97cc777c4301b8b0e9fa67f77959
  Sep 11 18:37:29 controller nova-compute[1278209]: INFO oslo_messaging._drivers.amqpdriver [-] Received RPC response for msg 96620f7bac8444aeb6c7e5a26fd831e3
  Sep 11 18:37:29 controller nova-compute[1278209]: DEBUG nova.compute.manager [None req-971d6eca-ac39-468d-849a-35fc4eeacdd6 None None] [instance: a713413f-cef5-4f32-9b34-b22c915e102c] Instance spawn was interrupted before instance_claim, setting instance to ERROR state {{(pid=1278209) _error_out_instances_whose_build_was_interrupted /opt/stack/nova/nova/compute/manager.py:1748}}

  
  Subsequent 'server show' with --debug does not show any ERROR states:

  REQ: curl -g -i -X GET http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c -H "OpenStack-API-Version: compute 2.96" -H "User-Agent: openstacksdk/3.3.0 keystoneauth1/5.7.0 python-requests/2.32.3 CPython/3.10.12" -H "X-Auth-Token: {SHA256}24ab2704d0f91fd353c3b525c11ad62a9eb0b901b5f6d97d6a5acbdf3c55184d" -H "X-OpenStack-Nova-API-Version: 2.96"
  Resetting dropped connection: 192.168.56.11
  http://192.168.56.11:80 "GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c HTTP/1.1" 200 1789
  RESP: [200] Connection: close Content-Length: 1789 Content-Type: application/json Date: Wed, 11 Sep 2024 19:24:50 GMT OpenStack-API-Version: compute 2.96 Server: Apache/2.4.52 (Ubuntu) Vary: OpenStack-API-Version,X-OpenStack-Nova-API-Version X-OpenStack-Nova-API-Version: 2.96 x-compute-request-id: req-6c490990-8b68-43ec-8d4d-14700f079e56 x-openstack-request-id: req-6c490990-8b68-43ec-8d4d-14700f079e56
  RESP BODY: {"server": {"id": "a713413f-cef5-4f32-9b34-b22c915e102c", "name": "debug", "status": "ACTIVE", "tenant_id": "2cee1a9455514ddb909a98d7eda1be50", "user_id": "e384582283d04540b3fa652efd85a913", "metadata": {}, "hostId": "075d4fd268d13c993ed6e9eb84ad44f016beff74f0cf7876aa471b05", "image": {"id": "5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea", "links": [{"rel": "bookmark", "href": "http://192.168.56.11/compute/images/5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea"}]}, "flavor": {"vcpus": 1, "ram": 512, "disk": 1, "ephemeral": 1, "swap": 512, "original_name": "m1.tiny.eph.swap", "extra_specs": {}}, "created": "2024-09-11T18:37:24Z", "updated": "2024-09-11T18:37:59Z", "addresses": {"private": [{"version": 6, "addr": "fd5e:b566:13f0:0:f816:3eff:fe45:c462", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:45:c4:62"}, {"version": 4, "addr": "10.0.0.21", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:45:c4:62"}]}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}, {"rel": "bookmark", "href": "http://192.168.56.11/compute/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}], "OS-DCF:diskConfig": "MANUAL", "progress": 0, "OS-EXT-AZ:availability_zone": "nova", "pinned_availability_zone": null, "config_drive": "", "key_name": null, "OS-SRV-USG:launched_at": "2024-09-11T18:37:58.000000", "OS-SRV-USG:terminated_at": null, "security_groups": [{"name": "default"}], "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "active", "OS-EXT-STS:power_state": 1, "os-extended-volumes:volumes_attached": [], "locked": false, "locked_reason": null, "description": "debug", "tags": [], "trusted_image_certificates": null, "OS-EXT-SRV-ATTR:hostname": "debug", "server_groups": []}}
  GET call to compute for http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c used request id req-6c490990-8b68-43ec-8d4d-14700f079e56
  REQ: curl -g -i -X GET http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c -H "OpenStack-API-Version: compute 2.96" -H "User-Agent: openstacksdk/3.3.0 keystoneauth1/5.7.0 python-requests/2.32.3 CPython/3.10.12" -H "X-Auth-Token: {SHA256}24ab2704d0f91fd353c3b525c11ad62a9eb0b901b5f6d97d6a5acbdf3c55184d" -H "X-OpenStack-Nova-API-Version: 2.96"
  Resetting dropped connection: 192.168.56.11
  http://192.168.56.11:80 "GET /compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c HTTP/1.1" 200 1789
  RESP: [200] Connection: close Content-Length: 1789 Content-Type: application/json Date: Wed, 11 Sep 2024 19:24:51 GMT OpenStack-API-Version: compute 2.96 Server: Apache/2.4.52 (Ubuntu) Vary: OpenStack-API-Version,X-OpenStack-Nova-API-Version X-OpenStack-Nova-API-Version: 2.96 x-compute-request-id: req-bb0029e7-d6d5-49c1-a06e-7bcfac66f016 x-openstack-request-id: req-bb0029e7-d6d5-49c1-a06e-7bcfac66f016
  RESP BODY: {"server": {"id": "a713413f-cef5-4f32-9b34-b22c915e102c", "name": "debug", "status": "ACTIVE", "tenant_id": "2cee1a9455514ddb909a98d7eda1be50", "user_id": "e384582283d04540b3fa652efd85a913", "metadata": {}, "hostId": "075d4fd268d13c993ed6e9eb84ad44f016beff74f0cf7876aa471b05", "image": {"id": "5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea", "links": [{"rel": "bookmark", "href": "http://192.168.56.11/compute/images/5c904e55-0e0d-4d6c-ae4a-393d93d9a3ea"}]}, "flavor": {"vcpus": 1, "ram": 512, "disk": 1, "ephemeral": 1, "swap": 512, "original_name": "m1.tiny.eph.swap", "extra_specs": {}}, "created": "2024-09-11T18:37:24Z", "updated": "2024-09-11T18:37:59Z", "addresses": {"private": [{"version": 6, "addr": "fd5e:b566:13f0:0:f816:3eff:fe45:c462", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:45:c4:62"}, {"version": 4, "addr": "10.0.0.21", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:45:c4:62"}]}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}, {"rel": "bookmark", "href": "http://192.168.56.11/compute/servers/a713413f-cef5-4f32-9b34-b22c915e102c"}], "OS-DCF:diskConfig": "MANUAL", "progress": 0, "OS-EXT-AZ:availability_zone": "nova", "pinned_availability_zone": null, "config_drive": "", "key_name": null, "OS-SRV-USG:launched_at": "2024-09-11T18:37:58.000000", "OS-SRV-USG:terminated_at": null, "security_groups": [{"name": "default"}], "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "active", "OS-EXT-STS:power_state": 1, "os-extended-volumes:volumes_attached": [], "locked": false, "locked_reason": null, "description": "debug", "tags": [], "trusted_image_certificates": null, "OS-EXT-SRV-ATTR:hostname": "debug", "server_groups": []}}
  GET call to compute for http://192.168.56.11/compute/v2.1/servers/a713413f-cef5-4f32-9b34-b22c915e102c used request id req-bb0029e7-d6d5-49c1-a06e-7bcfac66f016

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/2080427/+subscriptions