yahoo-eng-team team mailing list archive

[Bartosz Bezak <1916879@xxxxxxxxxxxxxxxxxx>]

Public bug reported:

Description
===========
Centos 8.3 Host - failed to attach second NIC on 1 vcpu ubuntu guests with qemu-kvm-5.1.0-14.el8.1.x86_64
Downgrading to qemu-kvm-4.2.0-29.el8.3.x86_64 fixes the problem.

First seen in Octavia:
http://lists.openstack.org/pipermail/openstack-discuss/2021-February/020218.html
https://storyboard.openstack.org/#!/story/2008651

Steps to reproduce
==================
Kayobe (kolla-ansible under the hood) deployed all-in-one on baremetal:
https://docs.openstack.org/kayobe/latest/contributor/automated.html#overcloud

ubuntu images - https://cloud-images.ubuntu.com/focal/current/focal-server-cloudimg-amd64.img
Problem reproduced on bionic, focal, groovy and hirsute.

Failing flavor - 1 VCPU - 16G RAM
Working flavor - 2 VCPUs - 1G RAM

openstack server create --flavor 16g --image focal --config-drive True --key-name test --network demo-net testvm16g
openstack --debug server add port testvm16g testvm1port

Expected result
===============
Proper attachment of NIC to VM

Actual result
=============

novaclient.exceptions.ClientException: Unknown Error (HTTP 504)
clean_up AddPort: Unknown Error (HTTP 504)

Environment
===========
1. Openstack Ussuri

openstack-nova-compute-21.1.2-1.el8.noarch
openstack-nova-common-21.1.2-1.el8.noarch

2. Which hypervisor did you use?
   Centos 8.3 - Libvirt + KVM

2. Which storage type did you use?
   SSD with ext4

3. Which networking type did you use?
   Tested on Neutron with OpenVSwitch, and Neutron with OVN

Logs & Configs
==============
Libvirt/Qemu logs are here:

http://paste.openstack.org/show/802996/

######################
openstack --debug server add port testvm16g testvm1port

Network client initialized using OpenStack SDK: <openstack.network.v2._proxy.Proxy object at 0x7ff4d30e7cf8>
REQ: curl -g -i -X GET http://192.168.33.2:9696/v2.0/ports/testvm1port -H "User-Agent: openstacksdk/0.46.0 keystoneauth1/4.0.0 python-requests/2.23.0 CPython/3.6.8" -H "X-Auth-Token: {SHA256}af6b741fc3c2fc134934a1cdfc10f75be456bb8536d64d4fe32559fb341d669d"
Starting new HTTP connection (1): 192.168.33.2:9696
http://192.168.33.2:9696 "GET /v2.0/ports/testvm1port HTTP/1.1" 404 107
RESP: [404] Connection: keep-alive Content-Length: 107 Content-Type: application/json Date: Thu, 25 Feb 2021 11:03:44 GMT X-Openstack-Request-Id: req-ba52034b-d259-44dc-a87f-93a26c9479f0
RESP BODY: {"NeutronError": {"type": "PortNotFound", "message": "Port testvm1port could not be found.", "detail": ""}}
GET call to network for http://192.168.33.2:9696/v2.0/ports/testvm1port used request id req-ba52034b-d259-44dc-a87f-93a26c9479f0
REQ: curl -g -i -X GET "http://192.168.33.2:9696/v2.0/ports?name=testvm1port"; -H "Accept: application/json" -H "User-Agent: openstacksdk/0.46.0 keystoneauth1/4.0.0 python-requests/2.23.0 CPython/3.6.8" -H "X-Auth-Token: {SHA256}af6b741fc3c2fc134934a1cdfc10f75be456bb8536d64d4fe32559fb341d669d"
http://192.168.33.2:9696 "GET /v2.0/ports?name=testvm1port HTTP/1.1" 200 805
RESP: [200] Connection: keep-alive Content-Length: 805 Content-Type: application/json Date: Thu, 25 Feb 2021 11:03:44 GMT X-Openstack-Request-Id: req-68eebc47-6a29-4c0c-ab35-26bd8138676c
RESP BODY: {"ports":[{"id":"409113d5-b275-48e8-8429-d08a06eb4caa","name":"testvm1port","network_id":"45c000ba-d770-48e3-8a83-5950c60e8a1d","tenant_id":"19303d9afcc4447b8985e7011add0d3d","mac_address":"fa:16:3e:aa:ce:9a","admin_state_up":true,"status":"DOWN","device_id":"","device_owner":"","fixed_ips":[{"subnet_id":"19164ffe-2c52-4233-b916-8448ee1e42a0","ip_address":"192.0.2.178"}],"allowed_address_pairs":[],"extra_dhcp_opts":[],"security_groups":["c997fbce-9065-47f5-9738-e311969c1db6"],"description":"","binding:vnic_type":"normal","binding:profile":{},"binding:host_id":"","binding:vif_type":"unbound","binding:vif_details":{},"port_security_enabled":true,"tags":[],"created_at":"2021-02-24T13:45:38Z","updated_at":"2021-02-25T10:06:27Z","revision_number":91,"project_id":"19303d9afcc4447b8985e7011add0d3d"}]}
GET call to network for http://192.168.33.2:9696/v2.0/ports?name=testvm1port used request id req-68eebc47-6a29-4c0c-ab35-26bd8138676c
REQ: curl -g -i -X POST http://192.168.33.2:8774/v2.1/servers/d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f/os-interface -H "Accept: application/json" -H "Content-Type: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: {SHA256}af6b741fc3c2fc134934a1cdfc10f75be456bb8536d64d4fe32559fb341d669d" -H "X-OpenStack-Nova-API-Version: 2.1" -d '{"interfaceAttachment": {"port_id": "409113d5-b275-48e8-8429-d08a06eb4caa"}}'
http://192.168.33.2:8774 "POST /v2.1/servers/d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f/os-interface HTTP/1.1" 504 None
RESP: [504] Cache-Control: no-cache Connection: close Content-Type: text/html
RESP BODY: Omitted, Content-Type is set to text/html. Only application/json responses have their bodies logged.
Unknown Error (HTTP 504)
Traceback (most recent call last):
  File "/home/centos/kayobe-venv/lib/python3.6/site-packages/cliff/app.py", line 401, in run_subcommand
    result = cmd.run(parsed_args)
  File "/home/centos/kayobe-venv/lib/python3.6/site-packages/osc_lib/command/command.py", line 41, in run
    return super(Command, self).run(parsed_args)
  File "/home/centos/kayobe-venv/lib/python3.6/site-packages/cliff/command.py", line 185, in run
    return_code = self.take_action(parsed_args) or 0
  File "/home/centos/kayobe-venv/lib/python3.6/site-packages/openstackclient/compute/v2/server.py", line 359, in take_action
    server.interface_attach(port_id=port_id, net_id=None, fixed_ip=None)
  File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/api_versions.py", line 393, in substitution
    return methods[-1].func(obj, *args, **kwargs)
  File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/v2/servers.py", line 610, in interface_attach
    return self.manager.interface_attach(self, port_id, net_id, fixed_ip)
  File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/api_versions.py", line 393, in substitution
    return methods[-1].func(obj, *args, **kwargs)
  File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/v2/servers.py", line 2063, in interface_attach
    obj_class=NetworkInterface)
  File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/base.py", line 363, in _create
    resp, body = self.api.client.post(url, body=body)
  File "/home/centos/kayobe-venv/lib/python3.6/site-packages/keystoneauth1/adapter.py", line 392, in post
    return self.request(url, 'POST', **kwargs)
  File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/client.py", line 78, in request
    raise exceptions.from_response(resp, body, url, method)
novaclient.exceptions.ClientException: Unknown Error (HTTP 504)
clean_up AddPort: Unknown Error (HTTP 504)
END return value: 1


#############################
nova-compute:

2021-02-25 11:03:46.549 7 DEBUG nova.network.os_vif_util [req-f47d8eee-0beb-4890-af38-e0d78cbfae88 8d64a09fc978483a9c9a64d71d863fb8 19303d9afcc4447b8985e7011add0d3d - default default] Converted object VIFOpenVSwitch(active=False,address=fa:16:3e:aa:ce:9a,bridge_name='br-int',has_traffic_filtering=True,id=409113d5-b275-48e8-8429-d08a06eb4caa,network=Network(45c000ba-d770-48e3-8a83-5950c60e8a1d),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=True,vif_name='tap409113d5-b2') nova_to_osvif_vif /usr/lib/python3.6/site-packages/nova/network/os_vif_util.py:538
2021-02-25 11:03:46.567 7 DEBUG nova.virt.libvirt.guest [req-f47d8eee-0beb-4890-af38-e0d78cbfae88 8d64a09fc978483a9c9a64d71d863fb8 19303d9afcc4447b8985e7011add0d3d - default default] attach device xml: <interface type="bridge">
  <mac address="fa:16:3e:aa:ce:9a"/>
  <model type="virtio"/>
  <driver name="qemu"/>
  <source bridge="br-int"/>
  <mtu size="1442"/>
  <target dev="tap409113d5-b2"/>
  <virtualport type="openvswitch">
    <parameters interfaceid="409113d5-b275-48e8-8429-d08a06eb4caa"/>
  </virtualport>
</interface>
 attach_device /usr/lib/python3.6/site-packages/nova/virt/libvirt/guest.py:292
2021-02-25 11:03:47.004 7 DEBUG nova.network.neutron [req-9ec4dc24-3aec-44c9-bb3d-3b4f9a398bc9 9ff617d4a7584f8b8fe1d40322430b5c 39cd2e2aa42b4eabb2fe199175406cda - default default] [instance: d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f] Updated VIF entry in instance network info cache for port 409113d5-b275-48e8-8429-d08a06eb4caa. _build_network_info_model /usr/lib/python3.6/site-packages/nova/network/neutron.py:3157
2021-02-25 11:03:47.005 7 DEBUG nova.network.neutron [req-9ec4dc24-3aec-44c9-bb3d-3b4f9a398bc9 9ff617d4a7584f8b8fe1d40322430b5c 39cd2e2aa42b4eabb2fe199175406cda - default default] [instance: d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f] Updating instance_info_cache with network_info: [{"id": "3dd3e38a-45ad-4e67-8b04-a9bb18ed372a", "address": "fa:16:3e:7d:98:04", "network": {"id": "dac630c1-4d4d-42b7-b2c7-f110697dc999", "bridge": "br-int", "label": "demo-net", "subnets": [{"cidr": "10.0.0.0/24", "dns": [{"address": "8.8.8.8", "type": "dns", "version": 4, "meta": {}}], "gateway": {"address": "10.0.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "10.0.0.174", "type": "fixed", "version": 4, "meta": {}, "floating_ips": [{"address": "192.168.33.96", "type": "floating", "version": 4, "meta": {}}]}], "routes": [], "version": 4, "meta": {"dhcp_server": "10.0.0.2"}}], "meta": {"injected": false, "tenant_id": "19303d9afcc4447b8985e7011add0d3d", "mtu": null, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true}, "devname": "tap3dd3e38a-45", "ovs_interfaceid": "3dd3e38a-45ad-4e67-8b04-a9bb18ed372a", "qbh_params": null, "qbg_params": null, "active": true, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "meta": {}}, {"id": "409113d5-b275-48e8-8429-d08a06eb4caa", "address": "fa:16:3e:aa:ce:9a", "network": {"id": "45c000ba-d770-48e3-8a83-5950c60e8a1d", "bridge": "br-int", "label": "test-net", "subnets": [{"cidr": "192.0.2.0/24", "dns": [], "gateway": {"address": "192.0.2.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "192.0.2.178", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"dhcp_server": "192.0.2.2"}}], "meta": {"injected": false, "tenant_id": "19303d9afcc4447b8985e7011add0d3d", "mtu": 1442, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true}, "devname": "tap409113d5-b2", "ovs_interfaceid": "409113d5-b275-48e8-8429-d08a06eb4caa", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": true, "meta": {}}] update_instance_cache_with_nw_info /usr/lib/python3.6/site-packages/nova/network/neutron.py:119

2021-02-25 11:03:48.335 7 WARNING nova.compute.manager [req-2a330fc9
-9bef-4f78-84cd-8b6a9e0158a8 9ff617d4a7584f8b8fe1d40322430b5c
39cd2e2aa42b4eabb2fe199175406cda - default default] [instance: d2a08a27
-5f9f-46f5-bbf0-f3920bd8cc9f] Received unexpected event network-vif-
plugged-409113d5-b275-48e8-8429-d08a06eb4caa for instance with vm_state
active and task_state None.

** Affects: nova
     Importance: Undecided
         Status: New

** Description changed:

  Description
  ===========
  Centos 8.3 Host - failed to attach second NIC on 1 vcpu ubuntu guests with qemu-kvm-5.1.0-14.el8.1.x86_64
  Downgrading to qemu-kvm-4.2.0-29.el8.3.x86_64 fixes the problem.
  
  First seen in Octavia:
  http://lists.openstack.org/pipermail/openstack-discuss/2021-February/020218.html
  https://storyboard.openstack.org/#!/story/2008651
- 
  
  Steps to reproduce
  ==================
  Kayobe (kolla-ansible under the hood) deployed all-in-one on baremetal:
  https://docs.openstack.org/kayobe/latest/contributor/automated.html#overcloud
  
  ubuntu images - https://cloud-images.ubuntu.com/focal/current/focal-server-cloudimg-amd64.img
  Problem reproduced on bionic, focal, groovy and hirsute.
  
  Failing flavor - 1 VCPU - 16G RAM
- Working flavor - 2 VCPUs - 1G RAM 
+ Working flavor - 2 VCPUs - 1G RAM
  
  openstack server create --flavor 16g --image focal --config-drive True --key-name test --network demo-net testvm16g
  openstack --debug server add port testvm16g testvm1port
  
  Expected result
  ===============
  Proper attachment of NIC to VM
  
  Actual result
  =============
  
  novaclient.exceptions.ClientException: Unknown Error (HTTP 504)
  clean_up AddPort: Unknown Error (HTTP 504)
  
  Environment
  ===========
  1. Openstack Ussuri
  
  openstack-nova-compute-21.1.2-1.el8.noarch
  openstack-nova-common-21.1.2-1.el8.noarch
  
  2. Which hypervisor did you use?
-    Centos 8.3 - Libvirt + KVM
+    Centos 8.3 - Libvirt + KVM
  
  2. Which storage type did you use?
-    SSD with ext4 
+    SSD with ext4
  
  3. Which networking type did you use?
-    Tested on Neutron with OpenVSwitch, and Neutron with OVN
+    Tested on Neutron with OpenVSwitch, and Neutron with OVN
  
  Logs & Configs
  ==============
+ Libvirt/Qemu logs are here:
+ 
+ http://paste.openstack.org/show/802996/
+ 
  openstack --debug server add port testvm16g testvm1port
  
  Network client initialized using OpenStack SDK: <openstack.network.v2._proxy.Proxy object at 0x7ff4d30e7cf8>
  REQ: curl -g -i -X GET http://192.168.33.2:9696/v2.0/ports/testvm1port -H "User-Agent: openstacksdk/0.46.0 keystoneauth1/4.0.0 python-requests/2.23.0 CPython/3.6.8" -H "X-Auth-Token: {SHA256}af6b741fc3c2fc134934a1cdfc10f75be456bb8536d64d4fe32559fb341d669d"
  Starting new HTTP connection (1): 192.168.33.2:9696
  http://192.168.33.2:9696 "GET /v2.0/ports/testvm1port HTTP/1.1" 404 107
  RESP: [404] Connection: keep-alive Content-Length: 107 Content-Type: application/json Date: Thu, 25 Feb 2021 11:03:44 GMT X-Openstack-Request-Id: req-ba52034b-d259-44dc-a87f-93a26c9479f0
  RESP BODY: {"NeutronError": {"type": "PortNotFound", "message": "Port testvm1port could not be found.", "detail": ""}}
  GET call to network for http://192.168.33.2:9696/v2.0/ports/testvm1port used request id req-ba52034b-d259-44dc-a87f-93a26c9479f0
  REQ: curl -g -i -X GET "http://192.168.33.2:9696/v2.0/ports?name=testvm1port"; -H "Accept: application/json" -H "User-Agent: openstacksdk/0.46.0 keystoneauth1/4.0.0 python-requests/2.23.0 CPython/3.6.8" -H "X-Auth-Token: {SHA256}af6b741fc3c2fc134934a1cdfc10f75be456bb8536d64d4fe32559fb341d669d"
  http://192.168.33.2:9696 "GET /v2.0/ports?name=testvm1port HTTP/1.1" 200 805
  RESP: [200] Connection: keep-alive Content-Length: 805 Content-Type: application/json Date: Thu, 25 Feb 2021 11:03:44 GMT X-Openstack-Request-Id: req-68eebc47-6a29-4c0c-ab35-26bd8138676c
  RESP BODY: {"ports":[{"id":"409113d5-b275-48e8-8429-d08a06eb4caa","name":"testvm1port","network_id":"45c000ba-d770-48e3-8a83-5950c60e8a1d","tenant_id":"19303d9afcc4447b8985e7011add0d3d","mac_address":"fa:16:3e:aa:ce:9a","admin_state_up":true,"status":"DOWN","device_id":"","device_owner":"","fixed_ips":[{"subnet_id":"19164ffe-2c52-4233-b916-8448ee1e42a0","ip_address":"192.0.2.178"}],"allowed_address_pairs":[],"extra_dhcp_opts":[],"security_groups":["c997fbce-9065-47f5-9738-e311969c1db6"],"description":"","binding:vnic_type":"normal","binding:profile":{},"binding:host_id":"","binding:vif_type":"unbound","binding:vif_details":{},"port_security_enabled":true,"tags":[],"created_at":"2021-02-24T13:45:38Z","updated_at":"2021-02-25T10:06:27Z","revision_number":91,"project_id":"19303d9afcc4447b8985e7011add0d3d"}]}
  GET call to network for http://192.168.33.2:9696/v2.0/ports?name=testvm1port used request id req-68eebc47-6a29-4c0c-ab35-26bd8138676c
  REQ: curl -g -i -X POST http://192.168.33.2:8774/v2.1/servers/d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f/os-interface -H "Accept: application/json" -H "Content-Type: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: {SHA256}af6b741fc3c2fc134934a1cdfc10f75be456bb8536d64d4fe32559fb341d669d" -H "X-OpenStack-Nova-API-Version: 2.1" -d '{"interfaceAttachment": {"port_id": "409113d5-b275-48e8-8429-d08a06eb4caa"}}'
  http://192.168.33.2:8774 "POST /v2.1/servers/d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f/os-interface HTTP/1.1" 504 None
  RESP: [504] Cache-Control: no-cache Connection: close Content-Type: text/html
  RESP BODY: Omitted, Content-Type is set to text/html. Only application/json responses have their bodies logged.
  Unknown Error (HTTP 504)
  Traceback (most recent call last):
-   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/cliff/app.py", line 401, in run_subcommand
-     result = cmd.run(parsed_args)
-   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/osc_lib/command/command.py", line 41, in run
-     return super(Command, self).run(parsed_args)
-   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/cliff/command.py", line 185, in run
-     return_code = self.take_action(parsed_args) or 0
-   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/openstackclient/compute/v2/server.py", line 359, in take_action
-     server.interface_attach(port_id=port_id, net_id=None, fixed_ip=None)
-   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/api_versions.py", line 393, in substitution
-     return methods[-1].func(obj, *args, **kwargs)
-   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/v2/servers.py", line 610, in interface_attach
-     return self.manager.interface_attach(self, port_id, net_id, fixed_ip)
-   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/api_versions.py", line 393, in substitution
-     return methods[-1].func(obj, *args, **kwargs)
-   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/v2/servers.py", line 2063, in interface_attach
-     obj_class=NetworkInterface)
-   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/base.py", line 363, in _create
-     resp, body = self.api.client.post(url, body=body)
-   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/keystoneauth1/adapter.py", line 392, in post
-     return self.request(url, 'POST', **kwargs)
-   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/client.py", line 78, in request
-     raise exceptions.from_response(resp, body, url, method)
+   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/cliff/app.py", line 401, in run_subcommand
+     result = cmd.run(parsed_args)
+   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/osc_lib/command/command.py", line 41, in run
+     return super(Command, self).run(parsed_args)
+   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/cliff/command.py", line 185, in run
+     return_code = self.take_action(parsed_args) or 0
+   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/openstackclient/compute/v2/server.py", line 359, in take_action
+     server.interface_attach(port_id=port_id, net_id=None, fixed_ip=None)
+   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/api_versions.py", line 393, in substitution
+     return methods[-1].func(obj, *args, **kwargs)
+   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/v2/servers.py", line 610, in interface_attach
+     return self.manager.interface_attach(self, port_id, net_id, fixed_ip)
+   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/api_versions.py", line 393, in substitution
+     return methods[-1].func(obj, *args, **kwargs)
+   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/v2/servers.py", line 2063, in interface_attach
+     obj_class=NetworkInterface)
+   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/base.py", line 363, in _create
+     resp, body = self.api.client.post(url, body=body)
+   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/keystoneauth1/adapter.py", line 392, in post
+     return self.request(url, 'POST', **kwargs)
+   File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/client.py", line 78, in request
+     raise exceptions.from_response(resp, body, url, method)
  novaclient.exceptions.ClientException: Unknown Error (HTTP 504)
  clean_up AddPort: Unknown Error (HTTP 504)
  END return value: 1
- 
  
  nova-compute:
  
  2021-02-25 11:03:46.549 7 DEBUG nova.network.os_vif_util [req-f47d8eee-0beb-4890-af38-e0d78cbfae88 8d64a09fc978483a9c9a64d71d863fb8 19303d9afcc4447b8985e7011add0d3d - default default] Converted object VIFOpenVSwitch(active=False,address=fa:16:3e:aa:ce:9a,bridge_name='br-int',has_traffic_filtering=True,id=409113d5-b275-48e8-8429-d08a06eb4caa,network=Network(45c000ba-d770-48e3-8a83-5950c60e8a1d),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=True,vif_name='tap409113d5-b2') nova_to_osvif_vif /usr/lib/python3.6/site-packages/nova/network/os_vif_util.py:538
  2021-02-25 11:03:46.567 7 DEBUG nova.virt.libvirt.guest [req-f47d8eee-0beb-4890-af38-e0d78cbfae88 8d64a09fc978483a9c9a64d71d863fb8 19303d9afcc4447b8985e7011add0d3d - default default] attach device xml: <interface type="bridge">
-   <mac address="fa:16:3e:aa:ce:9a"/>
-   <model type="virtio"/>
-   <driver name="qemu"/>
-   <source bridge="br-int"/>
-   <mtu size="1442"/>
-   <target dev="tap409113d5-b2"/>
-   <virtualport type="openvswitch">
-     <parameters interfaceid="409113d5-b275-48e8-8429-d08a06eb4caa"/>
-   </virtualport>
+   <mac address="fa:16:3e:aa:ce:9a"/>
+   <model type="virtio"/>
+   <driver name="qemu"/>
+   <source bridge="br-int"/>
+   <mtu size="1442"/>
+   <target dev="tap409113d5-b2"/>
+   <virtualport type="openvswitch">
+     <parameters interfaceid="409113d5-b275-48e8-8429-d08a06eb4caa"/>
+   </virtualport>
  </interface>
-  attach_device /usr/lib/python3.6/site-packages/nova/virt/libvirt/guest.py:292
+  attach_device /usr/lib/python3.6/site-packages/nova/virt/libvirt/guest.py:292
  2021-02-25 11:03:47.004 7 DEBUG nova.network.neutron [req-9ec4dc24-3aec-44c9-bb3d-3b4f9a398bc9 9ff617d4a7584f8b8fe1d40322430b5c 39cd2e2aa42b4eabb2fe199175406cda - default default] [instance: d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f] Updated VIF entry in instance network info cache for port 409113d5-b275-48e8-8429-d08a06eb4caa. _build_network_info_model /usr/lib/python3.6/site-packages/nova/network/neutron.py:3157
  2021-02-25 11:03:47.005 7 DEBUG nova.network.neutron [req-9ec4dc24-3aec-44c9-bb3d-3b4f9a398bc9 9ff617d4a7584f8b8fe1d40322430b5c 39cd2e2aa42b4eabb2fe199175406cda - default default] [instance: d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f] Updating instance_info_cache with network_info: [{"id": "3dd3e38a-45ad-4e67-8b04-a9bb18ed372a", "address": "fa:16:3e:7d:98:04", "network": {"id": "dac630c1-4d4d-42b7-b2c7-f110697dc999", "bridge": "br-int", "label": "demo-net", "subnets": [{"cidr": "10.0.0.0/24", "dns": [{"address": "8.8.8.8", "type": "dns", "version": 4, "meta": {}}], "gateway": {"address": "10.0.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "10.0.0.174", "type": "fixed", "version": 4, "meta": {}, "floating_ips": [{"address": "192.168.33.96", "type": "floating", "version": 4, "meta": {}}]}], "routes": [], "version": 4, "meta": {"dhcp_server": "10.0.0.2"}}], "meta": {"injected": false, "tenant_id": "19303d9afcc4447b8985e7011add0d3d", "mtu": null, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true}, "devname": "tap3dd3e38a-45", "ovs_interfaceid": "3dd3e38a-45ad-4e67-8b04-a9bb18ed372a", "qbh_params": null, "qbg_params": null, "active": true, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "meta": {}}, {"id": "409113d5-b275-48e8-8429-d08a06eb4caa", "address": "fa:16:3e:aa:ce:9a", "network": {"id": "45c000ba-d770-48e3-8a83-5950c60e8a1d", "bridge": "br-int", "label": "test-net", "subnets": [{"cidr": "192.0.2.0/24", "dns": [], "gateway": {"address": "192.0.2.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "192.0.2.178", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"dhcp_server": "192.0.2.2"}}], "meta": {"injected": false, "tenant_id": "19303d9afcc4447b8985e7011add0d3d", "mtu": 1442, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true}, "devname": "tap409113d5-b2", "ovs_interfaceid": "409113d5-b275-48e8-8429-d08a06eb4caa", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": true, "meta": {}}] update_instance_cache_with_nw_info /usr/lib/python3.6/site-packages/nova/network/neutron.py:119
  
  2021-02-25 11:03:48.335 7 WARNING nova.compute.manager [req-2a330fc9
  -9bef-4f78-84cd-8b6a9e0158a8 9ff617d4a7584f8b8fe1d40322430b5c
  39cd2e2aa42b4eabb2fe199175406cda - default default] [instance: d2a08a27
  -5f9f-46f5-bbf0-f3920bd8cc9f] Received unexpected event network-vif-
  plugged-409113d5-b275-48e8-8429-d08a06eb4caa for instance with vm_state
  active and task_state None.
- 
- Libvirt/qemu:
- 
- 2021-02-25 11:03:46.568+0000: 17285: debug : virDomainAttachDeviceFlags:8222 : dom=0x7f700400a9f0, (VM: name=instance-00000018, uuid=d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f), xml=<interface type="bridge">
-   <mac address="fa:16:3e:aa:ce:9a"/>
-   <model type="virtio"/>
-   <driver name="qemu"/>
-   <source bridge="br-int"/>
-   <mtu size="1442"/>
-   <target dev="tap409113d5-b2"/>
-   <virtualport type="openvswitch">
-     <parameters interfaceid="409113d5-b275-48e8-8429-d08a06eb4caa"/>
-   </virtualport>
- </interface>
- , flags=0x3
- 2021-02-25 11:03:46.568+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f7004116970
- 2021-02-25 11:03:46.568+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x5561fdc8adf0
- 2021-02-25 11:03:46.568+0000: 17285: debug : virAccessManagerCheckDomain:239 : manager=0x5561fdc8adf0(name=stack) driver=QEMU domain=0x7f705401c400 perm=2
- 2021-02-25 11:03:46.568+0000: 17285: debug : virAccessManagerCheckDomain:239 : manager=0x5561fdc8ae50(name=none) driver=QEMU domain=0x7f705401c400 perm=2
- 2021-02-25 11:03:46.568+0000: 17285: debug : virAccessManagerCheckDomain:239 : manager=0x5561fdc8adf0(name=stack) driver=QEMU domain=0x7f705401c400 perm=7
- 2021-02-25 11:03:46.568+0000: 17285: debug : virAccessManagerCheckDomain:239 : manager=0x5561fdc8ae50(name=none) driver=QEMU domain=0x7f705401c400 perm=7
- 2021-02-25 11:03:46.568+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x5561fdc8adf0
- 2021-02-25 11:03:46.568+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f7004114020
- 2021-02-25 11:03:46.568+0000: 17285: debug : qemuDomainObjBeginJobInternal:840 : Starting job: job=modify agentJob=none asyncJob=none (vm=0x7f7004116970 name=instance-00000018, current job=none agentJob=none async=none)
- 2021-02-25 11:03:46.568+0000: 17285: debug : qemuDomainObjBeginJobInternal:887 : Started job: modify (async=none vm=0x7f7004116970 name=instance-00000018)
- 2021-02-25 11:03:46.568+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f7004114020
- 2021-02-25 11:03:46.568+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f7004114020
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f6ffc098580 classname=qemuDomainVcpuPrivate
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f704403b550 classname=virStorageSource
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f6ff8007470 classname=qemuDomainDiskPrivate
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f704403b710 classname=virStorageSource
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f6ff80074d0 classname=qemuDomainDiskPrivate
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f7038005a80 classname=qemuDomainNetworkPrivate
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f6ffc19c400 classname=virDomainChrSourceDef
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f7038005ab0 classname=qemuDomainChrSourcePrivate
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f6ffc19c490 classname=virDomainChrSourceDef
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f7038005ae0 classname=qemuDomainChrSourcePrivate
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f705000d4d0 classname=qemuDomainGraphicsPrivate
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f7038005b10 classname=qemuDomainVideoPrivate
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f7004114020
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f7004114020
- 2021-02-25 11:03:46.569+0000: 17285: debug : qemuDomainAssignVirtioSerialAddresses:136 : Finished reserving existing ports
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:864 : PCI bus 0000:00 assigned isolation group 0 because of first device 0000:00:04.0
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:04.0 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:03.0 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:02.0 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:05.0 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:06.0 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.2 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.1 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.0 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.3 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:01 already in use
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:02 already in use
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:03 already in use
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:04 already in use
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:05 already in use
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:06 already in use
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressGetNextAddr:1234 : Found free PCI slot 0000:00:07
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:07.0 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:864 : PCI bus 0000:00 assigned isolation group 0 because of first device 0000:00:04.0
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:04.0 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:03.0 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:02.0 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:05.0 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:06.0 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.2 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.1 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.0 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.3 (aggregate='false')
- 2021-02-25 11:03:46.569+0000: 17285: debug : qemuDomainUSBAddressAddHubs:2999 : Found 1 USB devices and 2 provided USB ports; adding 0 hubs
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainUSBAddressSetAddController:2070 : Adding a USB controller model=piix3-uhci with 2 ports
- 2021-02-25 11:03:46.569+0000: 17285: debug : virDomainUSBAddressReserve:2404 : Reserving USB address bus=0 port=1
- 2021-02-25 11:03:46.569+0000: 17285: debug : qemuDomainAssignUSBAddresses:3138 : Existing USB addresses have been reserved
- 2021-02-25 11:03:46.569+0000: 17285: debug : qemuDomainAssignUSBAddresses:3146 : Finished assigning USB ports
- 2021-02-25 11:03:46.569+0000: 17285: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f7038005b40 classname=qemuDomainNetworkPrivate
- 2021-02-25 11:03:46.570+0000: 17285: debug : virFileClose:135 : Closed fd 27
- 2021-02-25 11:03:46.570+0000: 17285: debug : virFileClose:135 : Closed fd 27
- 2021-02-25 11:03:46.570+0000: 17285: debug : virArchFromHost:232 : Mapped x86_64 to 34 (x86_64)
- 2021-02-25 11:03:46.570+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f70040f3250
- 2021-02-25 11:03:46.570+0000: 17285: debug : virQEMUCapsCacheLookup:5656 : Returning caps 0x7f70040f3250 for /usr/libexec/qemu-kvm
- 2021-02-25 11:03:46.570+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f7004114020
- 2021-02-25 11:03:46.570+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f700414dd00
- 2021-02-25 11:03:46.570+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f7004114020
- 2021-02-25 11:03:46.570+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f700414dd00
- 2021-02-25 11:03:46.570+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f70040f3250
- 2021-02-25 11:03:46.570+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f7004114020
- 2021-02-25 11:03:46.570+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f7004114020
- 2021-02-25 11:03:46.570+0000: 17285: debug : qemuDomainAssignVirtioSerialAddresses:136 : Finished reserving existing ports
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:864 : PCI bus 0000:00 assigned isolation group 0 because of first device 0000:00:04.0
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:04.0 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:03.0 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:02.0 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:05.0 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:06.0 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.2 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.1 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.0 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.3 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:01 already in use
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:02 already in use
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:03 already in use
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:04 already in use
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:05 already in use
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:06 already in use
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressGetNextAddr:1234 : Found free PCI slot 0000:00:07
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:07.0 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:01 already in use
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:02 already in use
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:03 already in use
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:04 already in use
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:05 already in use
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:06 already in use
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:07 already in use
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressGetNextAddr:1234 : Found free PCI slot 0000:00:08
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:08.0 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:864 : PCI bus 0000:00 assigned isolation group 0 because of first device 0000:00:04.0
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:04.0 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:03.0 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:02.0 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:05.0 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:06.0 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.2 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.1 (aggregate='false')
- 2021-02-25 11:03:46.570+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.0 (aggregate='false')
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:01.3 (aggregate='false')
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:01 already in use
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:02 already in use
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:03 already in use
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:04 already in use
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:05 already in use
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:06 already in use
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressGetNextAddr:1234 : Found free PCI slot 0000:00:07
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:07.0 (aggregate='false')
- 2021-02-25 11:03:46.571+0000: 17285: debug : qemuDomainUSBAddressAddHubs:2999 : Found 1 USB devices and 2 provided USB ports; adding 0 hubs
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainUSBAddressSetAddController:2070 : Adding a USB controller model=piix3-uhci with 2 ports
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainUSBAddressReserve:2404 : Reserving USB address bus=0 port=1
- 2021-02-25 11:03:46.571+0000: 17285: debug : qemuDomainAssignUSBAddresses:3138 : Existing USB addresses have been reserved
- 2021-02-25 11:03:46.571+0000: 17285: debug : qemuDomainAssignUSBAddresses:3146 : Finished assigning USB ports
- 2021-02-25 11:03:46.571+0000: 17285: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f7038005b70 classname=qemuDomainNetworkPrivate
- 2021-02-25 11:03:46.571+0000: 17285: debug : virFileClose:135 : Closed fd 27
- 2021-02-25 11:03:46.571+0000: 17285: debug : virFileClose:135 : Closed fd 27
- 2021-02-25 11:03:46.571+0000: 17285: debug : virArchFromHost:232 : Mapped x86_64 to 34 (x86_64)
- 2021-02-25 11:03:46.571+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f70040f3250
- 2021-02-25 11:03:46.571+0000: 17285: debug : virQEMUCapsCacheLookup:5656 : Returning caps 0x7f70040f3250 for /usr/libexec/qemu-kvm
- 2021-02-25 11:03:46.571+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f7004114020
- 2021-02-25 11:03:46.571+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f700414dd00
- 2021-02-25 11:03:46.571+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f7004114020
- 2021-02-25 11:03:46.571+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f700414dd00
- 2021-02-25 11:03:46.571+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f70040f3250
- 2021-02-25 11:03:46.571+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f7004114020
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:01 already in use
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:02 already in use
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:03 already in use
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:04 already in use
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:05 already in use
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressFindUnusedFunctionOnBus:1141 : PCI slot 0000:00:06 already in use
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressGetNextAddr:1234 : Found free PCI slot 0000:00:07
- 2021-02-25 11:03:46.571+0000: 17285: debug : virDomainPCIAddressReserveAddrInternal:881 : Reserving PCI address 0000:00:07.0 (aggregate='false')
- 2021-02-25 11:03:46.571+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f7004114020
- 2021-02-25 11:03:46.571+0000: 17285: info : virNetDevProbeVnetHdr:234 : Enabling IFF_VNET_HDR
- 2021-02-25 11:03:46.571+0000: 17267: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 7
- 2021-02-25 11:03:46.571+0000: 17267: debug : virNetlinkEventCallback:875 : event not handled.
- 2021-02-25 11:03:46.571+0000: 17267: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 7
- 2021-02-25 11:03:46.571+0000: 17267: debug : virNetlinkEventCallback:875 : event not handled.
- 2021-02-25 11:03:46.571+0000: 17303: debug : udevHandleOneDevice:1500 : udev action: 'add'
- 2021-02-25 11:03:46.571+0000: 17303: debug : udevGetDeviceProperty:145 : Found property key 'DRIVER' value '<null>' for device with sysname 'tap409113d5-b2'
- 2021-02-25 11:03:46.571+0000: 17285: info : virNetDevTapCreate:403 : created device: 'tap409113d5-b2'
- 2021-02-25 11:03:46.571+0000: 17267: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 7
- 2021-02-25 11:03:46.571+0000: 17267: debug : virNetlinkEventCallback:875 : event not handled.
- 2021-02-25 11:03:46.571+0000: 17303: debug : udevGetDeviceProperty:145 : Found property key 'SUBSYSTEM' value 'net' for device with sysname 'tap409113d5-b2'
- 2021-02-25 11:03:46.571+0000: 17303: debug : udevGetDeviceProperty:145 : Found property key 'INTERFACE' value 'tap409113d5-b2' for device with sysname 'tap409113d5-b2'
- 2021-02-25 11:03:46.571+0000: 17303: debug : udevGetDeviceSysfsAttr:211 : Found sysfs attribute 'address' value 'fe:16:3e:aa:ce:9a' for device with sysname 'tap409113d5-b2'
- 2021-02-25 11:03:46.571+0000: 17285: debug : virNetDevSetMACInternal:280 : SIOCSIFHWADDR tap409113d5-b2 MAC=fe:16:3e:aa:ce:9a - Success
- 2021-02-25 11:03:46.571+0000: 17285: debug : virFileClose:135 : Closed fd 28
- 2021-02-25 11:03:46.571+0000: 17285: debug : virFileClose:135 : Closed fd 36
- 2021-02-25 11:03:46.571+0000: 17303: debug : udevGetDeviceSysfsAttr:211 : Found sysfs attribute 'addr_len' value '6' for device with sysname 'tap409113d5-b2'
- 2021-02-25 11:03:46.571+0000: 17285: debug : virFileClose:135 : Closed fd 28
- 2021-02-25 11:03:46.571+0000: 17303: debug : virFileClose:135 : Closed fd 28
- 2021-02-25 11:03:46.571+0000: 17285: debug : virCommandRunAsync:2618 : About to run ovs-vsctl --timeout=5 -- --if-exists del-port tap409113d5-b2 -- add-port br-int tap409113d5-b2 -- set Interface tap409113d5-b2 'external-ids:attached-mac="fa:16:3e:aa:ce:9a"' -- set Interface tap409113d5-b2 'external-ids:iface-id="409113d5-b275-48e8-8429-d08a06eb4caa"' -- set Interface tap409113d5-b2 'external-ids:vm-id="d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f"' -- set Interface tap409113d5-b2 external-ids:iface-status=active
- 2021-02-25 11:03:46.572+0000: 17303: debug : virFileClose:135 : Closed fd 28
- 2021-02-25 11:03:46.573+0000: 17285: debug : virFileClose:135 : Closed fd 36
- 2021-02-25 11:03:46.573+0000: 17285: debug : virFileClose:135 : Closed fd 37
- 2021-02-25 11:03:46.573+0000: 17285: debug : virFileClose:135 : Closed fd 39
- 2021-02-25 11:03:46.573+0000: 17285: debug : virCommandRunAsync:2621 : Command result 0, with PID 21403
- 2021-02-25 11:03:46.573+0000: 17303: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f704400fa50 classname=virNodeDeviceObj
- 2021-02-25 11:03:46.573+0000: 17303: info : virObjectRef:402 : OBJECT_REF: obj=0x7f704400fa50
- 2021-02-25 11:03:46.573+0000: 17303: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f6ff0006720 classname=virNodeDeviceEventLifecycle
- 2021-02-25 11:03:46.573+0000: 17303: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f704400fa50
- 2021-02-25 11:03:46.573+0000: 17303: info : vir_object_finalize:318 : OBJECT_DISPOSE: obj=0x7f6ff0006720
- 2021-02-25 11:03:46.573+0000: 17303: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0006720
- 2021-02-25 11:03:46.574+0000: 17303: debug : udevHandleOneDevice:1500 : udev action: 'add'
- 2021-02-25 11:03:46.574+0000: 17303: debug : udevGetDeviceProperty:145 : Found property key 'DRIVER' value '<null>' for device with sysname 'rx-0'
- 2021-02-25 11:03:46.574+0000: 17303: debug : udevGetDeviceProperty:145 : Found property key 'SUBSYSTEM' value 'queues' for device with sysname 'rx-0'
- 2021-02-25 11:03:46.574+0000: 17303: debug : udevGetDeviceType:1174 : Could not determine device type for device with sysfs name 'rx-0'
- 2021-02-25 11:03:46.574+0000: 17303: debug : udevAddOneDevice:1362 : Discarding device -1 0x7f6ff8004f10 /sys/devices/virtual/net/tap409113d5-b2/queues/rx-0
- 2021-02-25 11:03:46.574+0000: 17303: debug : udevHandleOneDevice:1500 : udev action: 'add'
- 2021-02-25 11:03:46.574+0000: 17303: debug : udevGetDeviceProperty:145 : Found property key 'DRIVER' value '<null>' for device with sysname 'tx-0'
- 2021-02-25 11:03:46.574+0000: 17303: debug : udevGetDeviceProperty:145 : Found property key 'SUBSYSTEM' value 'queues' for device with sysname 'tx-0'
- 2021-02-25 11:03:46.574+0000: 17303: debug : udevGetDeviceType:1174 : Could not determine device type for device with sysfs name 'tx-0'
- 2021-02-25 11:03:46.574+0000: 17303: debug : udevAddOneDevice:1362 : Discarding device -1 0x7f6ff8004f10 /sys/devices/virtual/net/tap409113d5-b2/queues/tx-0
- 2021-02-25 11:03:46.621+0000: 17285: debug : virCommandRun:2463 : Result status 0, stdout: '' stderr: ''
- 2021-02-25 11:03:46.621+0000: 17285: debug : virFileClose:135 : Closed fd 28
- 2021-02-25 11:03:46.621+0000: 17285: debug : virFileClose:135 : Closed fd 38
- 2021-02-25 11:03:46.621+0000: 17285: debug : virFileClose:135 : Closed fd 28
- 2021-02-25 11:03:46.621+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f7004114020
- 2021-02-25 11:03:46.621+0000: 17285: debug : virFileClose:135 : Closed fd 28
- 2021-02-25 11:03:46.621+0000: 17285: debug : qemuDomainObjEnterMonitorInternal:5495 : Entering monitor (mon=0x7f6ff0004440 vm=0x7f7004116970 name=instance-00000018)
- 2021-02-25 11:03:46.621+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.621+0000: 17285: debug : qemuMonitorAddNetdev:2693 : props=0x7f705a59b690 tapfd=0x7f70500193f0 tapfdName=0x7f7050024000 tapfdSize=1vhostfd=0x7f705001f2c0 vhostfdName=(nil) vhostfdSize=0slirpfd=-1 slirpfdName=(null)
- 2021-02-25 11:03:46.621+0000: 17285: debug : qemuMonitorAddNetdev:2695 : mon:0x7f6ff0004440 vm:0x7f7004116970 fd:34
- 2021-02-25 11:03:46.621+0000: 17285: debug : qemuMonitorSendFileHandle:2644 : fdname=fd-net10 fd=27
- 2021-02-25 11:03:46.621+0000: 17285: debug : qemuMonitorSendFileHandle:2646 : mon:0x7f6ff0004440 vm:0x7f7004116970 fd:34
- 2021-02-25 11:03:46.621+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.621+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.621+0000: 17285: info : qemuMonitorSend:946 : QEMU_MONITOR_SEND_MSG: mon=0x7f6ff0004440 msg={"execute":"getfd","arguments":{"fdname":"fd-net10"},"id":"libvirt-374"}
-  fd=27
- 2021-02-25 11:03:46.621+0000: 17797: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.621+0000: 17797: info : qemuMonitorIOWrite:433 : QEMU_MONITOR_IO_WRITE: mon=0x7f6ff0004440 buf={"execute":"getfd","arguments":{"fdname":"fd-net10"},"id":"libvirt-374"}
-  len=74 ret=74 errno=0
- 2021-02-25 11:03:46.622+0000: 17797: info : qemuMonitorIOWrite:438 : QEMU_MONITOR_IO_SEND_FD: mon=0x7f6ff0004440 fd=27 ret=74 errno=0
- 2021-02-25 11:03:46.622+0000: 17797: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.622+0000: 17797: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.622+0000: 17797: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.622+0000: 17797: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.622+0000: 17797: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"return": {}, "id": "libvirt-374"}]
- 2021-02-25 11:03:46.623+0000: 17797: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7f6ff0004440 reply={"return": {}, "id": "libvirt-374"}
- 2021-02-25 11:03:46.623+0000: 17797: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.623+0000: 17797: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.623+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.623+0000: 17797: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.623+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.623+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.623+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.623+0000: 17285: info : qemuMonitorSend:946 : QEMU_MONITOR_SEND_MSG: mon=0x7f6ff0004440 msg={"execute":"netdev_add","arguments":{"type":"tap","fd":"fd-net10","id":"hostnet1"},"id":"libvirt-375"}
-  fd=-1
- 2021-02-25 11:03:46.623+0000: 17797: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.623+0000: 17797: info : qemuMonitorIOWrite:433 : QEMU_MONITOR_IO_WRITE: mon=0x7f6ff0004440 buf={"execute":"netdev_add","arguments":{"type":"tap","fd":"fd-net10","id":"hostnet1"},"id":"libvirt-375"}
-  len=104 ret=104 errno=0
- 2021-02-25 11:03:46.623+0000: 17797: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.623+0000: 17797: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.623+0000: 17797: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.624+0000: 17797: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.624+0000: 17797: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"return": {}, "id": "libvirt-375"}]
- 2021-02-25 11:03:46.624+0000: 17797: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7f6ff0004440 reply={"return": {}, "id": "libvirt-375"}
- 2021-02-25 11:03:46.624+0000: 17797: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.624+0000: 17797: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.624+0000: 17797: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.624+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.624+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.624+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.624+0000: 17285: debug : qemuDomainObjExitMonitorInternal:5520 : Exited monitor (mon=0x7f6ff0004440 vm=0x7f7004116970 name=instance-00000018)
- 2021-02-25 11:03:46.624+0000: 17285: debug : virFileClose:135 : Closed fd 27
- 2021-02-25 11:03:46.624+0000: 17285: debug : qemuDomainObjEnterMonitorInternal:5495 : Entering monitor (mon=0x7f6ff0004440 vm=0x7f7004116970 name=instance-00000018)
- 2021-02-25 11:03:46.624+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.624+0000: 17285: debug : qemuMonitorAddDeviceWithFd:2841 : device=virtio-net-pci,host_mtu=1442,netdev=hostnet1,id=net1,mac=fa:16:3e:aa:ce:9a,bus=pci.0,addr=0x7 fd=-1 fdname=<null>
- 2021-02-25 11:03:46.624+0000: 17285: debug : qemuMonitorAddDeviceWithFd:2844 : mon:0x7f6ff0004440 vm:0x7f7004116970 fd:34
- 2021-02-25 11:03:46.624+0000: 17285: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.624+0000: 17285: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.624+0000: 17285: info : qemuMonitorSend:946 : QEMU_MONITOR_SEND_MSG: mon=0x7f6ff0004440 msg={"execute":"device_add","arguments":{"driver":"virtio-net-pci","host_mtu":"1442","netdev":"hostnet1","id":"net1","mac":"fa:16:3e:aa:ce:9a","bus":"pci.0","addr":"0x7"},"id":"libvirt-376"}
-  fd=-1
- 2021-02-25 11:03:46.624+0000: 17797: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.624+0000: 17797: info : qemuMonitorIOWrite:433 : QEMU_MONITOR_IO_WRITE: mon=0x7f6ff0004440 buf={"execute":"device_add","arguments":{"driver":"virtio-net-pci","host_mtu":"1442","netdev":"hostnet1","id":"net1","mac":"fa:16:3e:aa:ce:9a","bus":"pci.0","addr":"0x7"},"id":"libvirt-376"}
-  len=188 ret=188 errno=0
- 2021-02-25 11:03:46.624+0000: 17797: info : virObjectRef:402 : OBJECT_REF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.624+0000: 17797: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.624+0000: 17797: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff0004440
- 2021-02-25 11:03:46.920+0000: 17267: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 7
- 2021-02-25 11:03:46.920+0000: 17267: debug : virNetlinkEventCallback:875 : event not handled.
- 2021-02-25 11:03:46.920+0000: 17267: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 7
- 2021-02-25 11:03:46.920+0000: 17267: debug : virNetlinkEventCallback:875 : event not handled.
- 2021-02-25 11:03:46.920+0000: 17303: debug : udevHandleOneDevice:1500 : udev action: 'add'
- 2021-02-25 11:03:46.920+0000: 17303: debug : udevGetDeviceProperty:145 : Found property key 'DRIVER' value '<null>' for device with sysname 'tapddba2bff-00'
- 2021-02-25 11:03:46.920+0000: 17303: debug : udevGetDeviceProperty:145 : Found property key 'SUBSYSTEM' value 'net' for device with sysname 'tapddba2bff-00'
- 2021-02-25 11:03:46.920+0000: 17303: debug : udevGetDeviceProperty:145 : Found property key 'INTERFACE' value 'tapddba2bff-00' for device with sysname 'tapddba2bff-00'
- 2021-02-25 11:03:46.920+0000: 17267: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 7
- 2021-02-25 11:03:46.920+0000: 17267: debug : virNetlinkEventCallback:875 : event not handled.
- 2021-02-25 11:03:46.920+0000: 17303: debug : udevGetDeviceSysfsAttr:211 : Found sysfs attribute 'address' value '1e:3e:df:a6:d7:f1' for device with sysname 'tapddba2bff-00'
- 2021-02-25 11:03:46.920+0000: 17303: debug : udevGetDeviceSysfsAttr:211 : Found sysfs attribute 'addr_len' value '6' for device with sysname 'tapddba2bff-00'
- 2021-02-25 11:03:46.921+0000: 17303: debug : virFileClose:135 : Closed fd 27
- 2021-02-25 11:03:46.921+0000: 17303: debug : virFileClose:135 : Closed fd 27
- 2021-02-25 11:03:46.921+0000: 17303: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f704400fab0 classname=virNodeDeviceObj
- 2021-02-25 11:03:46.921+0000: 17303: info : virObjectRef:402 : OBJECT_REF: obj=0x7f704400fab0
- 2021-02-25 11:03:46.921+0000: 17303: info : virObjectNew:259 : OBJECT_NEW: obj=0x7f6ff8008050 classname=virNodeDeviceEventLifecycle
- 2021-02-25 11:03:46.921+0000: 17303: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f704400fab0
- 2021-02-25 11:03:46.921+0000: 17303: info : vir_object_finalize:318 : OBJECT_DISPOSE: obj=0x7f6ff8008050
- 2021-02-25 11:03:46.921+0000: 17303: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x7f6ff8008050
- 2021-02-25 11:03:46.921+0000: 17303: debug : udevHandleOneDevice:1500 : udev action: 'add'
- 2021-02-25 11:03:46.921+0000: 17303: debug : udevGetDeviceProperty:145 : Found property key 'DRIVER' value '<null>' for device with sysname 'rx-0'
- 2021-02-25 11:03:46.921+0000: 17303: debug : udevGetDeviceProperty:145 : Found property key 'SUBSYSTEM' value 'queues' for device with sysname 'rx-0'
- 2021-02-25 11:03:46.921+0000: 17303: debug : udevGetDeviceType:1174 : Could not determine device type for device with sysfs name 'rx-0'
- 2021-02-25 11:03:46.921+0000: 17303: debug : udevAddOneDevice:1362 : Discarding device -1 0x7f6ff8004700 /sys/devices/virtual/net/tapddba2bff-00/queues/rx-0
- 2021-02-25 11:03:46.921+0000: 17303: debug : udevHandleOneDevice:1500 : udev action: 'add'
- 2021-02-25 11:03:46.921+0000: 17303: debug : udevGetDeviceProperty:145 : Found property key 'DRIVER' value '<null>' for device with sysname 'tx-0'
- 2021-02-25 11:03:46.921+0000: 17303: debug : udevGetDeviceProperty:145 : Found property key 'SUBSYSTEM' value 'queues' for device with sysname 'tx-0'
- 2021-02-25 11:03:46.921+0000: 17303: debug : udevGetDeviceType:1174 : Could not determine device type for device with sysfs name 'tx-0'
- 2021-02-25 11:03:46.921+0000: 17303: debug : udevAddOneDevice:1362 : Discarding device -1 0x7f6ff8004700 /sys/devices/virtual/net/tapddba2bff-00/queues/tx-0
- 2021-02-25 11:03:51.573+0000: 17267: info : virObjectRef:402 : OBJECT_REF: obj=0x5561fdcb48d0
- 2021-02-25 11:03:51.573+0000: 17267: info : virObjectUnref:380 : OBJECT_UNREF: obj=0x5561fdcb48d0
- 2021-02-25 11:03:53.517+0000: 17267: info : virObjectRef:402 : OBJECT_REF: obj=0x5561fdcb6080

** Description changed:

  Description
  ===========
  Centos 8.3 Host - failed to attach second NIC on 1 vcpu ubuntu guests with qemu-kvm-5.1.0-14.el8.1.x86_64
  Downgrading to qemu-kvm-4.2.0-29.el8.3.x86_64 fixes the problem.
  
  First seen in Octavia:
  http://lists.openstack.org/pipermail/openstack-discuss/2021-February/020218.html
  https://storyboard.openstack.org/#!/story/2008651
  
  Steps to reproduce
  ==================
  Kayobe (kolla-ansible under the hood) deployed all-in-one on baremetal:
  https://docs.openstack.org/kayobe/latest/contributor/automated.html#overcloud
  
  ubuntu images - https://cloud-images.ubuntu.com/focal/current/focal-server-cloudimg-amd64.img
  Problem reproduced on bionic, focal, groovy and hirsute.
  
  Failing flavor - 1 VCPU - 16G RAM
  Working flavor - 2 VCPUs - 1G RAM
  
  openstack server create --flavor 16g --image focal --config-drive True --key-name test --network demo-net testvm16g
  openstack --debug server add port testvm16g testvm1port
  
  Expected result
  ===============
  Proper attachment of NIC to VM
  
  Actual result
  =============
  
  novaclient.exceptions.ClientException: Unknown Error (HTTP 504)
  clean_up AddPort: Unknown Error (HTTP 504)
  
  Environment
  ===========
  1. Openstack Ussuri
  
  openstack-nova-compute-21.1.2-1.el8.noarch
  openstack-nova-common-21.1.2-1.el8.noarch
  
  2. Which hypervisor did you use?
     Centos 8.3 - Libvirt + KVM
  
  2. Which storage type did you use?
     SSD with ext4
  
  3. Which networking type did you use?
     Tested on Neutron with OpenVSwitch, and Neutron with OVN
  
  Logs & Configs
  ==============
  Libvirt/Qemu logs are here:
  
  http://paste.openstack.org/show/802996/
  
+ ######################
  openstack --debug server add port testvm16g testvm1port
  
  Network client initialized using OpenStack SDK: <openstack.network.v2._proxy.Proxy object at 0x7ff4d30e7cf8>
  REQ: curl -g -i -X GET http://192.168.33.2:9696/v2.0/ports/testvm1port -H "User-Agent: openstacksdk/0.46.0 keystoneauth1/4.0.0 python-requests/2.23.0 CPython/3.6.8" -H "X-Auth-Token: {SHA256}af6b741fc3c2fc134934a1cdfc10f75be456bb8536d64d4fe32559fb341d669d"
  Starting new HTTP connection (1): 192.168.33.2:9696
  http://192.168.33.2:9696 "GET /v2.0/ports/testvm1port HTTP/1.1" 404 107
  RESP: [404] Connection: keep-alive Content-Length: 107 Content-Type: application/json Date: Thu, 25 Feb 2021 11:03:44 GMT X-Openstack-Request-Id: req-ba52034b-d259-44dc-a87f-93a26c9479f0
  RESP BODY: {"NeutronError": {"type": "PortNotFound", "message": "Port testvm1port could not be found.", "detail": ""}}
  GET call to network for http://192.168.33.2:9696/v2.0/ports/testvm1port used request id req-ba52034b-d259-44dc-a87f-93a26c9479f0
  REQ: curl -g -i -X GET "http://192.168.33.2:9696/v2.0/ports?name=testvm1port"; -H "Accept: application/json" -H "User-Agent: openstacksdk/0.46.0 keystoneauth1/4.0.0 python-requests/2.23.0 CPython/3.6.8" -H "X-Auth-Token: {SHA256}af6b741fc3c2fc134934a1cdfc10f75be456bb8536d64d4fe32559fb341d669d"
  http://192.168.33.2:9696 "GET /v2.0/ports?name=testvm1port HTTP/1.1" 200 805
  RESP: [200] Connection: keep-alive Content-Length: 805 Content-Type: application/json Date: Thu, 25 Feb 2021 11:03:44 GMT X-Openstack-Request-Id: req-68eebc47-6a29-4c0c-ab35-26bd8138676c
  RESP BODY: {"ports":[{"id":"409113d5-b275-48e8-8429-d08a06eb4caa","name":"testvm1port","network_id":"45c000ba-d770-48e3-8a83-5950c60e8a1d","tenant_id":"19303d9afcc4447b8985e7011add0d3d","mac_address":"fa:16:3e:aa:ce:9a","admin_state_up":true,"status":"DOWN","device_id":"","device_owner":"","fixed_ips":[{"subnet_id":"19164ffe-2c52-4233-b916-8448ee1e42a0","ip_address":"192.0.2.178"}],"allowed_address_pairs":[],"extra_dhcp_opts":[],"security_groups":["c997fbce-9065-47f5-9738-e311969c1db6"],"description":"","binding:vnic_type":"normal","binding:profile":{},"binding:host_id":"","binding:vif_type":"unbound","binding:vif_details":{},"port_security_enabled":true,"tags":[],"created_at":"2021-02-24T13:45:38Z","updated_at":"2021-02-25T10:06:27Z","revision_number":91,"project_id":"19303d9afcc4447b8985e7011add0d3d"}]}
  GET call to network for http://192.168.33.2:9696/v2.0/ports?name=testvm1port used request id req-68eebc47-6a29-4c0c-ab35-26bd8138676c
  REQ: curl -g -i -X POST http://192.168.33.2:8774/v2.1/servers/d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f/os-interface -H "Accept: application/json" -H "Content-Type: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: {SHA256}af6b741fc3c2fc134934a1cdfc10f75be456bb8536d64d4fe32559fb341d669d" -H "X-OpenStack-Nova-API-Version: 2.1" -d '{"interfaceAttachment": {"port_id": "409113d5-b275-48e8-8429-d08a06eb4caa"}}'
  http://192.168.33.2:8774 "POST /v2.1/servers/d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f/os-interface HTTP/1.1" 504 None
  RESP: [504] Cache-Control: no-cache Connection: close Content-Type: text/html
  RESP BODY: Omitted, Content-Type is set to text/html. Only application/json responses have their bodies logged.
  Unknown Error (HTTP 504)
  Traceback (most recent call last):
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/cliff/app.py", line 401, in run_subcommand
      result = cmd.run(parsed_args)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/osc_lib/command/command.py", line 41, in run
      return super(Command, self).run(parsed_args)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/cliff/command.py", line 185, in run
      return_code = self.take_action(parsed_args) or 0
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/openstackclient/compute/v2/server.py", line 359, in take_action
      server.interface_attach(port_id=port_id, net_id=None, fixed_ip=None)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/api_versions.py", line 393, in substitution
      return methods[-1].func(obj, *args, **kwargs)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/v2/servers.py", line 610, in interface_attach
      return self.manager.interface_attach(self, port_id, net_id, fixed_ip)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/api_versions.py", line 393, in substitution
      return methods[-1].func(obj, *args, **kwargs)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/v2/servers.py", line 2063, in interface_attach
      obj_class=NetworkInterface)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/base.py", line 363, in _create
      resp, body = self.api.client.post(url, body=body)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/keystoneauth1/adapter.py", line 392, in post
      return self.request(url, 'POST', **kwargs)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/client.py", line 78, in request
      raise exceptions.from_response(resp, body, url, method)
  novaclient.exceptions.ClientException: Unknown Error (HTTP 504)
  clean_up AddPort: Unknown Error (HTTP 504)
  END return value: 1
  
+ 
+ #############################
  nova-compute:
  
  2021-02-25 11:03:46.549 7 DEBUG nova.network.os_vif_util [req-f47d8eee-0beb-4890-af38-e0d78cbfae88 8d64a09fc978483a9c9a64d71d863fb8 19303d9afcc4447b8985e7011add0d3d - default default] Converted object VIFOpenVSwitch(active=False,address=fa:16:3e:aa:ce:9a,bridge_name='br-int',has_traffic_filtering=True,id=409113d5-b275-48e8-8429-d08a06eb4caa,network=Network(45c000ba-d770-48e3-8a83-5950c60e8a1d),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=True,vif_name='tap409113d5-b2') nova_to_osvif_vif /usr/lib/python3.6/site-packages/nova/network/os_vif_util.py:538
  2021-02-25 11:03:46.567 7 DEBUG nova.virt.libvirt.guest [req-f47d8eee-0beb-4890-af38-e0d78cbfae88 8d64a09fc978483a9c9a64d71d863fb8 19303d9afcc4447b8985e7011add0d3d - default default] attach device xml: <interface type="bridge">
    <mac address="fa:16:3e:aa:ce:9a"/>
    <model type="virtio"/>
    <driver name="qemu"/>
    <source bridge="br-int"/>
    <mtu size="1442"/>
    <target dev="tap409113d5-b2"/>
    <virtualport type="openvswitch">
      <parameters interfaceid="409113d5-b275-48e8-8429-d08a06eb4caa"/>
    </virtualport>
  </interface>
   attach_device /usr/lib/python3.6/site-packages/nova/virt/libvirt/guest.py:292
  2021-02-25 11:03:47.004 7 DEBUG nova.network.neutron [req-9ec4dc24-3aec-44c9-bb3d-3b4f9a398bc9 9ff617d4a7584f8b8fe1d40322430b5c 39cd2e2aa42b4eabb2fe199175406cda - default default] [instance: d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f] Updated VIF entry in instance network info cache for port 409113d5-b275-48e8-8429-d08a06eb4caa. _build_network_info_model /usr/lib/python3.6/site-packages/nova/network/neutron.py:3157
  2021-02-25 11:03:47.005 7 DEBUG nova.network.neutron [req-9ec4dc24-3aec-44c9-bb3d-3b4f9a398bc9 9ff617d4a7584f8b8fe1d40322430b5c 39cd2e2aa42b4eabb2fe199175406cda - default default] [instance: d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f] Updating instance_info_cache with network_info: [{"id": "3dd3e38a-45ad-4e67-8b04-a9bb18ed372a", "address": "fa:16:3e:7d:98:04", "network": {"id": "dac630c1-4d4d-42b7-b2c7-f110697dc999", "bridge": "br-int", "label": "demo-net", "subnets": [{"cidr": "10.0.0.0/24", "dns": [{"address": "8.8.8.8", "type": "dns", "version": 4, "meta": {}}], "gateway": {"address": "10.0.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "10.0.0.174", "type": "fixed", "version": 4, "meta": {}, "floating_ips": [{"address": "192.168.33.96", "type": "floating", "version": 4, "meta": {}}]}], "routes": [], "version": 4, "meta": {"dhcp_server": "10.0.0.2"}}], "meta": {"injected": false, "tenant_id": "19303d9afcc4447b8985e7011add0d3d", "mtu": null, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true}, "devname": "tap3dd3e38a-45", "ovs_interfaceid": "3dd3e38a-45ad-4e67-8b04-a9bb18ed372a", "qbh_params": null, "qbg_params": null, "active": true, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "meta": {}}, {"id": "409113d5-b275-48e8-8429-d08a06eb4caa", "address": "fa:16:3e:aa:ce:9a", "network": {"id": "45c000ba-d770-48e3-8a83-5950c60e8a1d", "bridge": "br-int", "label": "test-net", "subnets": [{"cidr": "192.0.2.0/24", "dns": [], "gateway": {"address": "192.0.2.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "192.0.2.178", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"dhcp_server": "192.0.2.2"}}], "meta": {"injected": false, "tenant_id": "19303d9afcc4447b8985e7011add0d3d", "mtu": 1442, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true}, "devname": "tap409113d5-b2", "ovs_interfaceid": "409113d5-b275-48e8-8429-d08a06eb4caa", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": true, "meta": {}}] update_instance_cache_with_nw_info /usr/lib/python3.6/site-packages/nova/network/neutron.py:119
  
  2021-02-25 11:03:48.335 7 WARNING nova.compute.manager [req-2a330fc9
  -9bef-4f78-84cd-8b6a9e0158a8 9ff617d4a7584f8b8fe1d40322430b5c
  39cd2e2aa42b4eabb2fe199175406cda - default default] [instance: d2a08a27
  -5f9f-46f5-bbf0-f3920bd8cc9f] Received unexpected event network-vif-
  plugged-409113d5-b275-48e8-8429-d08a06eb4caa for instance with vm_state
  active and task_state None.

-- 
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/1916879

Title:
  Failed to attach second NIC on 1 vcpu ubuntu guests  with qemu-kvm
  5.1.0

Status in OpenStack Compute (nova):
  New

Bug description:
  Description
  ===========
  Centos 8.3 Host - failed to attach second NIC on 1 vcpu ubuntu guests with qemu-kvm-5.1.0-14.el8.1.x86_64
  Downgrading to qemu-kvm-4.2.0-29.el8.3.x86_64 fixes the problem.

  First seen in Octavia:
  http://lists.openstack.org/pipermail/openstack-discuss/2021-February/020218.html
  https://storyboard.openstack.org/#!/story/2008651

  Steps to reproduce
  ==================
  Kayobe (kolla-ansible under the hood) deployed all-in-one on baremetal:
  https://docs.openstack.org/kayobe/latest/contributor/automated.html#overcloud

  ubuntu images - https://cloud-images.ubuntu.com/focal/current/focal-server-cloudimg-amd64.img
  Problem reproduced on bionic, focal, groovy and hirsute.

  Failing flavor - 1 VCPU - 16G RAM
  Working flavor - 2 VCPUs - 1G RAM

  openstack server create --flavor 16g --image focal --config-drive True --key-name test --network demo-net testvm16g
  openstack --debug server add port testvm16g testvm1port

  Expected result
  ===============
  Proper attachment of NIC to VM

  Actual result
  =============

  novaclient.exceptions.ClientException: Unknown Error (HTTP 504)
  clean_up AddPort: Unknown Error (HTTP 504)

  Environment
  ===========
  1. Openstack Ussuri

  openstack-nova-compute-21.1.2-1.el8.noarch
  openstack-nova-common-21.1.2-1.el8.noarch

  2. Which hypervisor did you use?
     Centos 8.3 - Libvirt + KVM

  2. Which storage type did you use?
     SSD with ext4

  3. Which networking type did you use?
     Tested on Neutron with OpenVSwitch, and Neutron with OVN

  Logs & Configs
  ==============
  Libvirt/Qemu logs are here:

  http://paste.openstack.org/show/802996/

  ######################
  openstack --debug server add port testvm16g testvm1port

  Network client initialized using OpenStack SDK: <openstack.network.v2._proxy.Proxy object at 0x7ff4d30e7cf8>
  REQ: curl -g -i -X GET http://192.168.33.2:9696/v2.0/ports/testvm1port -H "User-Agent: openstacksdk/0.46.0 keystoneauth1/4.0.0 python-requests/2.23.0 CPython/3.6.8" -H "X-Auth-Token: {SHA256}af6b741fc3c2fc134934a1cdfc10f75be456bb8536d64d4fe32559fb341d669d"
  Starting new HTTP connection (1): 192.168.33.2:9696
  http://192.168.33.2:9696 "GET /v2.0/ports/testvm1port HTTP/1.1" 404 107
  RESP: [404] Connection: keep-alive Content-Length: 107 Content-Type: application/json Date: Thu, 25 Feb 2021 11:03:44 GMT X-Openstack-Request-Id: req-ba52034b-d259-44dc-a87f-93a26c9479f0
  RESP BODY: {"NeutronError": {"type": "PortNotFound", "message": "Port testvm1port could not be found.", "detail": ""}}
  GET call to network for http://192.168.33.2:9696/v2.0/ports/testvm1port used request id req-ba52034b-d259-44dc-a87f-93a26c9479f0
  REQ: curl -g -i -X GET "http://192.168.33.2:9696/v2.0/ports?name=testvm1port"; -H "Accept: application/json" -H "User-Agent: openstacksdk/0.46.0 keystoneauth1/4.0.0 python-requests/2.23.0 CPython/3.6.8" -H "X-Auth-Token: {SHA256}af6b741fc3c2fc134934a1cdfc10f75be456bb8536d64d4fe32559fb341d669d"
  http://192.168.33.2:9696 "GET /v2.0/ports?name=testvm1port HTTP/1.1" 200 805
  RESP: [200] Connection: keep-alive Content-Length: 805 Content-Type: application/json Date: Thu, 25 Feb 2021 11:03:44 GMT X-Openstack-Request-Id: req-68eebc47-6a29-4c0c-ab35-26bd8138676c
  RESP BODY: {"ports":[{"id":"409113d5-b275-48e8-8429-d08a06eb4caa","name":"testvm1port","network_id":"45c000ba-d770-48e3-8a83-5950c60e8a1d","tenant_id":"19303d9afcc4447b8985e7011add0d3d","mac_address":"fa:16:3e:aa:ce:9a","admin_state_up":true,"status":"DOWN","device_id":"","device_owner":"","fixed_ips":[{"subnet_id":"19164ffe-2c52-4233-b916-8448ee1e42a0","ip_address":"192.0.2.178"}],"allowed_address_pairs":[],"extra_dhcp_opts":[],"security_groups":["c997fbce-9065-47f5-9738-e311969c1db6"],"description":"","binding:vnic_type":"normal","binding:profile":{},"binding:host_id":"","binding:vif_type":"unbound","binding:vif_details":{},"port_security_enabled":true,"tags":[],"created_at":"2021-02-24T13:45:38Z","updated_at":"2021-02-25T10:06:27Z","revision_number":91,"project_id":"19303d9afcc4447b8985e7011add0d3d"}]}
  GET call to network for http://192.168.33.2:9696/v2.0/ports?name=testvm1port used request id req-68eebc47-6a29-4c0c-ab35-26bd8138676c
  REQ: curl -g -i -X POST http://192.168.33.2:8774/v2.1/servers/d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f/os-interface -H "Accept: application/json" -H "Content-Type: application/json" -H "User-Agent: python-novaclient" -H "X-Auth-Token: {SHA256}af6b741fc3c2fc134934a1cdfc10f75be456bb8536d64d4fe32559fb341d669d" -H "X-OpenStack-Nova-API-Version: 2.1" -d '{"interfaceAttachment": {"port_id": "409113d5-b275-48e8-8429-d08a06eb4caa"}}'
  http://192.168.33.2:8774 "POST /v2.1/servers/d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f/os-interface HTTP/1.1" 504 None
  RESP: [504] Cache-Control: no-cache Connection: close Content-Type: text/html
  RESP BODY: Omitted, Content-Type is set to text/html. Only application/json responses have their bodies logged.
  Unknown Error (HTTP 504)
  Traceback (most recent call last):
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/cliff/app.py", line 401, in run_subcommand
      result = cmd.run(parsed_args)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/osc_lib/command/command.py", line 41, in run
      return super(Command, self).run(parsed_args)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/cliff/command.py", line 185, in run
      return_code = self.take_action(parsed_args) or 0
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/openstackclient/compute/v2/server.py", line 359, in take_action
      server.interface_attach(port_id=port_id, net_id=None, fixed_ip=None)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/api_versions.py", line 393, in substitution
      return methods[-1].func(obj, *args, **kwargs)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/v2/servers.py", line 610, in interface_attach
      return self.manager.interface_attach(self, port_id, net_id, fixed_ip)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/api_versions.py", line 393, in substitution
      return methods[-1].func(obj, *args, **kwargs)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/v2/servers.py", line 2063, in interface_attach
      obj_class=NetworkInterface)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/base.py", line 363, in _create
      resp, body = self.api.client.post(url, body=body)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/keystoneauth1/adapter.py", line 392, in post
      return self.request(url, 'POST', **kwargs)
    File "/home/centos/kayobe-venv/lib/python3.6/site-packages/novaclient/client.py", line 78, in request
      raise exceptions.from_response(resp, body, url, method)
  novaclient.exceptions.ClientException: Unknown Error (HTTP 504)
  clean_up AddPort: Unknown Error (HTTP 504)
  END return value: 1

  
  #############################
  nova-compute:

  2021-02-25 11:03:46.549 7 DEBUG nova.network.os_vif_util [req-f47d8eee-0beb-4890-af38-e0d78cbfae88 8d64a09fc978483a9c9a64d71d863fb8 19303d9afcc4447b8985e7011add0d3d - default default] Converted object VIFOpenVSwitch(active=False,address=fa:16:3e:aa:ce:9a,bridge_name='br-int',has_traffic_filtering=True,id=409113d5-b275-48e8-8429-d08a06eb4caa,network=Network(45c000ba-d770-48e3-8a83-5950c60e8a1d),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=True,vif_name='tap409113d5-b2') nova_to_osvif_vif /usr/lib/python3.6/site-packages/nova/network/os_vif_util.py:538
  2021-02-25 11:03:46.567 7 DEBUG nova.virt.libvirt.guest [req-f47d8eee-0beb-4890-af38-e0d78cbfae88 8d64a09fc978483a9c9a64d71d863fb8 19303d9afcc4447b8985e7011add0d3d - default default] attach device xml: <interface type="bridge">
    <mac address="fa:16:3e:aa:ce:9a"/>
    <model type="virtio"/>
    <driver name="qemu"/>
    <source bridge="br-int"/>
    <mtu size="1442"/>
    <target dev="tap409113d5-b2"/>
    <virtualport type="openvswitch">
      <parameters interfaceid="409113d5-b275-48e8-8429-d08a06eb4caa"/>
    </virtualport>
  </interface>
   attach_device /usr/lib/python3.6/site-packages/nova/virt/libvirt/guest.py:292
  2021-02-25 11:03:47.004 7 DEBUG nova.network.neutron [req-9ec4dc24-3aec-44c9-bb3d-3b4f9a398bc9 9ff617d4a7584f8b8fe1d40322430b5c 39cd2e2aa42b4eabb2fe199175406cda - default default] [instance: d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f] Updated VIF entry in instance network info cache for port 409113d5-b275-48e8-8429-d08a06eb4caa. _build_network_info_model /usr/lib/python3.6/site-packages/nova/network/neutron.py:3157
  2021-02-25 11:03:47.005 7 DEBUG nova.network.neutron [req-9ec4dc24-3aec-44c9-bb3d-3b4f9a398bc9 9ff617d4a7584f8b8fe1d40322430b5c 39cd2e2aa42b4eabb2fe199175406cda - default default] [instance: d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f] Updating instance_info_cache with network_info: [{"id": "3dd3e38a-45ad-4e67-8b04-a9bb18ed372a", "address": "fa:16:3e:7d:98:04", "network": {"id": "dac630c1-4d4d-42b7-b2c7-f110697dc999", "bridge": "br-int", "label": "demo-net", "subnets": [{"cidr": "10.0.0.0/24", "dns": [{"address": "8.8.8.8", "type": "dns", "version": 4, "meta": {}}], "gateway": {"address": "10.0.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "10.0.0.174", "type": "fixed", "version": 4, "meta": {}, "floating_ips": [{"address": "192.168.33.96", "type": "floating", "version": 4, "meta": {}}]}], "routes": [], "version": 4, "meta": {"dhcp_server": "10.0.0.2"}}], "meta": {"injected": false, "tenant_id": "19303d9afcc4447b8985e7011add0d3d", "mtu": null, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true}, "devname": "tap3dd3e38a-45", "ovs_interfaceid": "3dd3e38a-45ad-4e67-8b04-a9bb18ed372a", "qbh_params": null, "qbg_params": null, "active": true, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "meta": {}}, {"id": "409113d5-b275-48e8-8429-d08a06eb4caa", "address": "fa:16:3e:aa:ce:9a", "network": {"id": "45c000ba-d770-48e3-8a83-5950c60e8a1d", "bridge": "br-int", "label": "test-net", "subnets": [{"cidr": "192.0.2.0/24", "dns": [], "gateway": {"address": "192.0.2.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "192.0.2.178", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"dhcp_server": "192.0.2.2"}}], "meta": {"injected": false, "tenant_id": "19303d9afcc4447b8985e7011add0d3d", "mtu": 1442, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true}, "devname": "tap409113d5-b2", "ovs_interfaceid": "409113d5-b275-48e8-8429-d08a06eb4caa", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": true, "meta": {}}] update_instance_cache_with_nw_info /usr/lib/python3.6/site-packages/nova/network/neutron.py:119

  2021-02-25 11:03:48.335 7 WARNING nova.compute.manager [req-2a330fc9
  -9bef-4f78-84cd-8b6a9e0158a8 9ff617d4a7584f8b8fe1d40322430b5c
  39cd2e2aa42b4eabb2fe199175406cda - default default] [instance:
  d2a08a27-5f9f-46f5-bbf0-f3920bd8cc9f] Received unexpected event
  network-vif-plugged-409113d5-b275-48e8-8429-d08a06eb4caa for instance
  with vm_state active and task_state None.

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