OpenStack Compute (nova)

  1. Bug #1957939
  2. Comment #8

Comment 8 for bug 1957939

Revision history for this message
Pavel Mracek (mrakotiq) wrote :

I also hit this bug and found some interesting log lines on node where the vm should have been resized. It looks like the port removal event comes at a time when the vm is already removed. And throw exeption in /usr/lib/python3/dist-packages/nova/compute/manager.py on line 10542 (xena), or in master here https://github.com/openstack/nova/blob/aad31e6ba489f720f5bdc765c132fd0f059a0329/nova/compute/manager.py#L10834

... but why the event/error is not delivered and the request ends with a timeout, I don't know.

Hope this helps:

Log from "destination" node
#############################
2022-10-04 11:23:04.610 1978602 INFO nova.virt.libvirt.driver [-] [instance: b6713c7b-78b2-4a98-9fd9-d15bba46e7b6] Instance destroyed successfully.
2022-10-04 11:23:04.691 1978602 INFO nova.virt.libvirt.driver [req-02388e45-5075-4b7c-bd51-813f450d0031 50764bebfebd116f803dd84621c29053b54595d95b67f9d2b5fbb2717d69a656 9a0c0e73b2e04a90a7f0de3a4ba391c9 - default default] [instance: b6713c7b-78b2-4a98-9fd9-d15bba46e7b6] Deleting instance files /var/lib/nova/instances/b6713c7b-78b2-4a98-9fd9-d15bba46e7b6_del
2022-10-04 11:23:05.974 1978602 INFO nova.virt.libvirt.driver [req-02388e45-5075-4b7c-bd51-813f450d0031 50764bebfebd116f803dd84621c29053b54595d95b67f9d2b5fbb2717d69a656 9a0c0e73b2e04a90a7f0de3a4ba391c9 - default default] [instance: b6713c7b-78b2-4a98-9fd9-d15bba46e7b6] Deletion of /var/lib/nova/instances/b6713c7b-78b2-4a98-9fd9-d15bba46e7b6_del complete
2022-10-04 11:23:06.792 1978602 WARNING nova.compute.manager [req-7f65479a-15f5-401d-a966-75b0ab57dccb ffcb10315af847c9bc45971bea122fb7 - - b7913c95910e4431a16009e665db28bc -] [instance: b6713c7b-78b2-4a98-9fd9-d15bba46e7b6] Received unexpected event network-vif-unplugged-1f532f40-5723-4e5b-bb6f-34d544e85896 for instance with vm_state resized and task_state resize_reverting.
2022-10-04 11:23:08.836 1978602 WARNING nova.compute.manager [req-c359ae0a-ee99-422a-a150-2c6be0d18774 ffcb10315af847c9bc45971bea122fb7 - - b7913c95910e4431a16009e665db28bc -] [instance: b6713c7b-78b2-4a98-9fd9-d15bba46e7b6] Received unexpected event network-vif-plugged-1f532f40-5723-4e5b-bb6f-34d544e85896 for instance with vm_state resized and task_state resize_reverting.
vvvvv
2022-10-04 11:23:09.145 1978602 INFO nova.compute.manager [req-793b4785-a4e7-4515-aa6d-050d27726911 ffcb10315af847c9bc45971bea122fb7 - - b7913c95910e4431a16009e665db28bc -] [instance: b6713c7b-78b2-4a98-9fd9-d15bba46e7b6] Failed to process external instance event network-changed-1f532f40-5723-4e5b-bb6f-34d544e85896 due to: Instance b6713c7b-78b2-4a98-9fd9-d15bba46e7b6 could not be found.
^^^^^
2022-10-04 11:23:19.613 1978602 INFO nova.compute.manager [-] [instance: b6713c7b-78b2-4a98-9fd9-d15bba46e7b6] VM Stopped (Lifecycle Event)
2022-10-04 11:28:12.084 1978602 WARNING nova.compute.manager [req-f5ddf196-9dd4-4ec4-ad06-ded090886a0a ffcb10315af847c9bc45971bea122fb7 - - b7913c95910e4431a16009e665db28bc -] [instance: b6713c7b-78b2-4a98-9fd9-d15bba46e7b6] Received unexpected event network-vif-unplugged-1f532f40-5723-4e5b-bb6f-34d544e85896 for instance with vm_state error and task_state None.

Logs from controllers splited by req-id:
########################################
req-02388e45-5075-4b7c-bd51-813f450d0031 (original request from cli client "resize revert")
04 11:23:03.277 /var/log/nova/nova-api.log:2022-10-04 11:23:03.277 4100519 INFO nova.osapi_compute.wsgi.server [req-02388e45-5075-4b7c-bd51-813f450d0031 50764bebfebd116f803dd84621c29053b54595d95b67f9d2b5fbb2717d69a656 9a0c0e73b2e04a90a7f0de3a4ba391c9 - default default] 10.16.0.90,127.0.0.1 "POST /v2.1/servers/b6713c7b-78b2-4a98-9fd9-d15bba46e7b6/action HTTP/1.0" status: 202 len: 398 time: 0.1846585

# req-793b4785-a4e7-4515-aa6d-050d27726911 (erroneous "external instance event network-changed")
/var/log/nova/nova-api.log:2022-10-04 11:23:08.378 4018451 INFO nova.api.openstack.compute.server_external_events [req-793b4785-a4e7-4515-aa6d-050d27726911 ffcb10315af847c9bc45971bea122fb7 - - b7913c95910e4431a16009e665db28bc -] Creating event network-changed:1f532f40-5723-4e5b-bb6f-34d544e85896 for instance b6713c7b-78b2-4a98-9fd9-d15bba46e7b6 on tt-os1-n249
/var/log/nova/nova-api.log:2022-10-04 11:23:08.391 4018451 INFO nova.osapi_compute.wsgi.server [req-793b4785-a4e7-4515-aa6d-050d27726911 ffcb10315af847c9bc45971bea122fb7 - - b7913c95910e4431a16009e665db28bc -] 10.255.18.0(our API address),127.0.0.1 "POST /v2.1/os-server-external-events HTTP/1.0" status: 200 len: 573 time: 0.2344851
/var/log/neutron/neutron-server.log:2022-10-04 11:23:08.392 4018569 INFO neutron.notifiers.nova [-] Nova event matching ['req-793b4785-a4e7-4515-aa6d-050d27726911'] response: {'name': 'network-changed', 'server_uuid': 'b6713c7b-78b2-4a98-9fd9-d15bba46e7b6', 'tag': '1f532f40-5723-4e5b-bb6f-34d544e85896', 'status': 'completed', 'code': 200}

# req-7f65479a-15f5-401d-a966-75b0ab57dccb (event network-vif-unplugged)
04 11:23:06.781 /var/log/nova/nova-api.log:2022-10-04 11:23:06.781 185659 INFO nova.api.openstack.compute.server_external_events [req-7f65479a-15f5-401d-a966-75b0ab57dccb ffcb10315af847c9bc45971bea122fb7 - - b7913c95910e4431a16009e665db28bc -] Creating event network-vif-unplugged:1f532f40-5723-4e5b-bb6f-34d544e85896 for instance b6713c7b-78b2-4a98-9fd9-d15bba46e7b6 on tt-os1-n249.ko.iszn.cz
04 11:23:06.794 /var/log/nova/nova-api.log:2022-10-04 11:23:06.794 185659 INFO nova.osapi_compute.wsgi.server [req-7f65479a-15f5-401d-a966-75b0ab57dccb ffcb10315af847c9bc45971bea122fb7 - - b7913c95910e4431a16009e665db28bc -] 10.255.18.0,127.0.0.1 "POST /v2.1/os-server-external-events HTTP/1.0" status: 200 len: 579 time: 0.3066220
04 11:23:06.800 /var/log/neutron/neutron-server.log:2022-10-04 11:23:06.800 185636 INFO neutron.notifiers.nova [-] Nova event matching ['req-7f65479a-15f5-401d-a966-75b0ab57dccb'] response: {'server_uuid': 'b6713c7b-78b2-4a98-9fd9-d15bba46e7b6', 'name': 'network-vif-unplugged', 'status': 'completed', 'tag': '1f532f40-5723-4e5b-bb6f-34d544e85896', 'code': 200}

# req-c359ae0a-ee99-422a-a150-2c6be0d18774 (event network-vif-plugged)
04 11:23:08.826 /var/log/nova/nova-api.log:2022-10-04 11:23:08.826 185656 INFO nova.api.openstack.compute.server_external_events [req-c359ae0a-ee99-422a-a150-2c6be0d18774 ffcb10315af847c9bc45971bea122fb7 - - b7913c95910e4431a16009e665db28bc -] Creating event network-vif-plugged:1f532f40-5723-4e5b-bb6f-34d544e85896 for instance b6713c7b-78b2-4a98-9fd9-d15bba46e7b6 on tt-os1-n249.ko.iszn.cz
04 11:23:08.838 /var/log/nova/nova-api.log:2022-10-04 11:23:08.838 185656 INFO nova.osapi_compute.wsgi.server [req-c359ae0a-ee99-422a-a150-2c6be0d18774 ffcb10315af847c9bc45971bea122fb7 - - b7913c95910e4431a16009e665db28bc -] 10.255.18.0,127.0.0.1 "POST /v2.1/os-server-external-events HTTP/1.0" status: 200 len: 577 time: 0.0298991
04 11:23:08.934 /var/log/neutron/neutron-server.log:2022-10-04 11:23:08.934 185636 INFO neutron.notifiers.nova [-] Nova event matching ['req-c359ae0a-ee99-422a-a150-2c6be0d18774'] response: {'server_uuid': 'b6713c7b-78b2-4a98-9fd9-d15bba46e7b6', 'name': 'network-vif-plugged', 'status': 'completed', 'tag': '1f532f40-5723-4e5b-bb6f-34d544e85896', 'code': 200}

# And finaly log from source node: (req-02388e45-5075-4b7c-bd51-813f450d0031)
######################################
2022-10-04 11:23:06.485 2972585 INFO nova.compute.manager [req-02388e45-5075-4b7c-bd51-813f450d0031 50764bebfebd116f803dd84621c29053b54595d95b67f9d2b5fbb2717d69a656 9a0c0e73b2e04a90a7f0de3a4ba391c9 - default default] [instance: b6713c7b-78b2-4a98-9fd9-d15bba46e7b6] Swapping old allocation on dict_keys(['5d7b163f-84e1-475f-b4f8-f8546f0389af']) held by migration 6784a842-ae47-41f4-b3e8-831226cc7a4a for instance
2022-10-04 11:23:06.626 2972585 INFO nova.network.neutron [req-02388e45-5075-4b7c-bd51-813f450d0031 50764bebfebd116f803dd84621c29053b54595d95b67f9d2b5fbb2717d69a656 9a0c0e73b2e04a90a7f0de3a4ba391c9 - default default] [instance: b6713c7b-78b2-4a98-9fd9-d15bba46e7b6] Updating port 1f532f40-5723-4e5b-bb6f-34d544e85896 with attributes {'binding:host_id': 'tt-os1-n249', 'device_owner': 'compute:az1'}
#(and after 300s)
2022-10-04 11:28:09.616 2972585 WARNING nova.virt.libvirt.driver [req-02388e45-5075-4b7c-bd51-813f450d0031 50764bebfebd116f803dd84621c29053b54595d95b67f9d2b5fbb2717d69a656 9a0c0e73b2e04a90a7f0de3a4ba391c9 - default default] [instance: b6713c7b-78b2-4a98-9fd9-d15bba46e7b6] Timeout waiting for [('network-vif-plugged', '1f532f40-5723-4e5b-bb6f-34d544e85896')] for instance with vm_state resized and task_state resize_reverting: eventlet.timeout.Timeout: 300 seconds
2022-10-04 11:28:09.910 2972585 INFO nova.virt.libvirt.host [req-02388e45-5075-4b7c-bd51-813f450d0031 50764bebfebd116f803dd84621c29053b54595d95b67f9d2b5fbb2717d69a656 9a0c0e73b2e04a90a7f0de3a4ba391c9 - default default] UEFI support detected
2022-10-04 11:28:09.912 2972585 ERROR nova.compute.manager [req-02388e45-5075-4b7c-bd51-813f450d0031 50764bebfebd116f803dd84621c29053b54595d95b67f9d2b5fbb2717d69a656 9a0c0e73b2e04a90a7f0de3a4ba391c9 - default default] [instance: b6713c7b-78b2-4a98-9fd9-d15bba46e7b6] Setting instance vm_state to ERROR: nova.exception.VirtualInterfaceCreateException: Virtual Interface creation failed