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': '2cee1a94 55514ddb909a98d7eda1be50', '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_zo ne": "", "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", "c onfig_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,encrypti on_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': '2cee1a 9455514ddb909a98d7eda1be50', '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,encryp tion_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 -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : yahoo-eng-team@lists.launchpad.net Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
