OpenStack Compute (nova)

test_interface_detach_with_port_with_bandwidth_request intermittently fails

Bug #1819374 reported by Matt Riedemann
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Medium
Balazs Gibizer

Bug Description

Seen here:

http://logs.openstack.org/21/641021/1/gate/nova-tox-functional-py35/b057262/job-output.txt.gz#_2019-03-09_17_01_22_053827

2019-03-09 17:01:22.053827 | ubuntu-xenial | {1} nova.tests.functional.test_servers.PortResourceRequestBasedSchedulingTest.test_interface_detach_with_port_with_bandwidth_request [3.961215s] ... FAILED
2019-03-09 17:01:22.053957 | ubuntu-xenial |
2019-03-09 17:01:22.053999 | ubuntu-xenial | Captured pythonlogging:
2019-03-09 17:01:22.054050 | ubuntu-xenial | ~~~~~~~~~~~~~~~~~~~~~~~
2019-03-09 17:01:22.054142 | ubuntu-xenial | b'2019-03-09 17:01:18,266 WARNING [placement.db_api] TransactionFactory already started, not reconfiguring.'
2019-03-09 17:01:22.054231 | ubuntu-xenial | b'2019-03-09 17:01:19,023 INFO [nova.service] Starting conductor node (version 18.1.0)'
2019-03-09 17:01:22.054328 | ubuntu-xenial | b'2019-03-09 17:01:19,046 INFO [nova.service] Starting scheduler node (version 18.1.0)'
2019-03-09 17:01:22.054415 | ubuntu-xenial | b"2019-03-09 17:01:19,073 INFO [nova.virt.driver] Loading compute driver 'fake.FakeDriverWithPciResources'"
2019-03-09 17:01:22.054558 | ubuntu-xenial | b'2019-03-09 17:01:19,073 WARNING [nova.compute.monitors] Excluding nova.compute.monitors.cpu monitor virt_driver. Not in the list of enabled monitors (CONF.compute_monitors).'
2019-03-09 17:01:22.054651 | ubuntu-xenial | b'2019-03-09 17:01:19,075 INFO [nova.service] Starting compute node (version 18.1.0)'
2019-03-09 17:01:22.054800 | ubuntu-xenial | b'2019-03-09 17:01:19,104 WARNING [nova.compute.manager] No compute node record found for host host1. If this is the first time this service is starting on this host, then you can ignore this warning.'
2019-03-09 17:01:22.054886 | ubuntu-xenial | b'2019-03-09 17:01:19,110 WARNING [nova.compute.resource_tracker] No compute node record for host1:host1'
2019-03-09 17:01:22.055002 | ubuntu-xenial | b'2019-03-09 17:01:19,115 INFO [nova.compute.resource_tracker] Compute node record created for host1:host1 with uuid: 0e59ca49-7858-479c-8b7c-13a78199a981'
2019-03-09 17:01:22.055174 | ubuntu-xenial | b'2019-03-09 17:01:19,167 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?in_tree=0e59ca49-7858-479c-8b7c-13a78199a981" status: 200 len: 26 microversion: 1.14'
2019-03-09 17:01:22.055329 | ubuntu-xenial | b'2019-03-09 17:01:19,178 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 828 microversion: 1.20'
2019-03-09 17:01:22.055522 | ubuntu-xenial | b'2019-03-09 17:01:19,179 INFO [nova.scheduler.client.report] [req-40799b9c-9042-4da4-bd70-e4afd7bc1632] Created resource provider record via placement API for resource provider with UUID 0e59ca49-7858-479c-8b7c-13a78199a981 and name host1.'
2019-03-09 17:01:22.055677 | ubuntu-xenial | b'2019-03-09 17:01:19,196 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/0e59ca49-7858-479c-8b7c-13a78199a981/inventories" status: 200 len: 399 microversion: 1.26'
2019-03-09 17:01:22.055888 | ubuntu-xenial | b'2019-03-09 17:01:19,204 INFO [placement.requestlog] 127.0.0.1 "GET /placement/traits?name=in:COMPUTE_VOLUME_MULTI_ATTACH,COMPUTE_TRUSTED_CERTS,COMPUTE_NET_ATTACH_INTERFACE_WITH_TAG,COMPUTE_VOLUME_EXTEND,COMPUTE_VOLUME_ATTACH_WITH_TAG,COMPUTE_NET_ATTACH_INTERFACE" status: 200 len: 200 microversion: 1.6'
2019-03-09 17:01:22.056067 | ubuntu-xenial | b'2019-03-09 17:01:19,222 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/0e59ca49-7858-479c-8b7c-13a78199a981/traits" status: 200 len: 235 microversion: 1.6'
2019-03-09 17:01:22.056176 | ubuntu-xenial | b'2019-03-09 17:01:19,268 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1" status: 204 len: 0 microversion: - time: 0.000463'
2019-03-09 17:01:22.056355 | ubuntu-xenial | b'2019-03-09 17:01:19,311 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/os-hypervisors?hypervisor_hostname_pattern=host1" status: 200 len: 133 microversion: 2.72 time: 0.040365'
2019-03-09 17:01:22.056549 | ubuntu-xenial | b'2019-03-09 17:01:19,331 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/flavors/detail" status: 200 len: 3043 microversion: 2.72 time: 0.015999'
2019-03-09 17:01:22.056691 | ubuntu-xenial | b'2019-03-09 17:01:19,351 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/flavors/detail" status: 200 len: 3043 microversion: 2.72 time: 0.015321'
2019-03-09 17:01:22.056833 | ubuntu-xenial | b'2019-03-09 17:01:19,379 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/flavors/2/os-extra_specs" status: 200 len: 44 microversion: 2.72 time: 0.024595'
2019-03-09 17:01:22.056948 | ubuntu-xenial | b'2019-03-09 17:01:19,392 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 893 microversion: 1.20'
2019-03-09 17:01:22.057055 | ubuntu-xenial | b'2019-03-09 17:01:19,403 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 893 microversion: 1.20'
2019-03-09 17:01:22.057182 | ubuntu-xenial | b'2019-03-09 17:01:19,412 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/e409c184-d60f-4770-a8b0-5a40b50f1b1c" status: 200 len: 437 microversion: 1.0'
2019-03-09 17:01:22.057332 | ubuntu-xenial | b'2019-03-09 17:01:19,425 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/e409c184-d60f-4770-a8b0-5a40b50f1b1c/inventories" status: 200 len: 338 microversion: 1.0'
2019-03-09 17:01:22.057450 | ubuntu-xenial | b'2019-03-09 17:01:19,433 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/traits/CUSTOM_VNIC_TYPE_NORMAL" status: 201 len: 0 microversion: 1.6'
2019-03-09 17:01:22.057557 | ubuntu-xenial | b'2019-03-09 17:01:19,440 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/traits/CUSTOM_PHYSNET2" status: 201 len: 0 microversion: 1.6'
2019-03-09 17:01:22.057683 | ubuntu-xenial | b'2019-03-09 17:01:19,448 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/e409c184-d60f-4770-a8b0-5a40b50f1b1c" status: 200 len: 437 microversion: 1.0'
2019-03-09 17:01:22.057813 | ubuntu-xenial | b'2019-03-09 17:01:19,465 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/e409c184-d60f-4770-a8b0-5a40b50f1b1c/traits" status: 200 len: 93 microversion: 1.6'
2019-03-09 17:01:22.057971 | ubuntu-xenial | b'2019-03-09 17:01:19,479 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 910 microversion: 1.20'
2019-03-09 17:01:22.058088 | ubuntu-xenial | b'2019-03-09 17:01:19,491 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 915 microversion: 1.20'
2019-03-09 17:01:22.058219 | ubuntu-xenial | b'2019-03-09 17:01:19,500 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/f92fd9c1-c5b8-4195-beeb-f2c94bd245c1" status: 200 len: 459 microversion: 1.0'
2019-03-09 17:01:22.058372 | ubuntu-xenial | b'2019-03-09 17:01:19,514 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/f92fd9c1-c5b8-4195-beeb-f2c94bd245c1/inventories" status: 200 len: 340 microversion: 1.0'
2019-03-09 17:01:22.058489 | ubuntu-xenial | b'2019-03-09 17:01:19,522 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/traits/CUSTOM_VNIC_TYPE_DIRECT" status: 201 len: 0 microversion: 1.6'
2019-03-09 17:01:22.058619 | ubuntu-xenial | b'2019-03-09 17:01:19,529 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/traits/CUSTOM_PHYSNET1" status: 201 len: 0 microversion: 1.6'
2019-03-09 17:01:22.058754 | ubuntu-xenial | b'2019-03-09 17:01:19,538 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/f92fd9c1-c5b8-4195-beeb-f2c94bd245c1" status: 200 len: 459 microversion: 1.0'
2019-03-09 17:01:22.058885 | ubuntu-xenial | b'2019-03-09 17:01:19,555 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/f92fd9c1-c5b8-4195-beeb-f2c94bd245c1/traits" status: 200 len: 93 microversion: 1.6'
2019-03-09 17:01:22.058991 | ubuntu-xenial | b'2019-03-09 17:01:19,566 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 915 microversion: 1.20'
2019-03-09 17:01:22.059119 | ubuntu-xenial | b'2019-03-09 17:01:19,576 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/214f1a72-51c0-45af-b958-12f568c77be5" status: 200 len: 459 microversion: 1.0'
2019-03-09 17:01:22.059272 | ubuntu-xenial | b'2019-03-09 17:01:19,589 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/214f1a72-51c0-45af-b958-12f568c77be5/inventories" status: 200 len: 340 microversion: 1.0'
2019-03-09 17:01:22.059402 | ubuntu-xenial | b'2019-03-09 17:01:19,597 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/traits/CUSTOM_VNIC_TYPE_DIRECT" status: 204 len: 0 microversion: 1.6'
2019-03-09 17:01:22.059509 | ubuntu-xenial | b'2019-03-09 17:01:19,604 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/traits/CUSTOM_PHYSNET2" status: 204 len: 0 microversion: 1.6'
2019-03-09 17:01:22.059636 | ubuntu-xenial | b'2019-03-09 17:01:19,613 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/214f1a72-51c0-45af-b958-12f568c77be5" status: 200 len: 459 microversion: 1.0'
2019-03-09 17:01:22.059772 | ubuntu-xenial | b'2019-03-09 17:01:19,630 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/214f1a72-51c0-45af-b958-12f568c77be5/traits" status: 200 len: 93 microversion: 1.6'
2019-03-09 17:01:22.059878 | ubuntu-xenial | b'2019-03-09 17:01:19,642 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 915 microversion: 1.20'
2019-03-09 17:01:22.060005 | ubuntu-xenial | b'2019-03-09 17:01:19,651 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/74dcdd80-1057-4aef-9cfd-e4014af28b8e" status: 200 len: 459 microversion: 1.0'
2019-03-09 17:01:22.060139 | ubuntu-xenial | b'2019-03-09 17:01:19,664 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/74dcdd80-1057-4aef-9cfd-e4014af28b8e/inventories" status: 200 len: 54 microversion: 1.0'
2019-03-09 17:01:22.060263 | ubuntu-xenial | b'2019-03-09 17:01:19,672 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/traits/CUSTOM_VNIC_TYPE_DIRECT" status: 204 len: 0 microversion: 1.6'
2019-03-09 17:01:22.060408 | ubuntu-xenial | b'2019-03-09 17:01:19,680 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/traits/CUSTOM_PHYSNET2" status: 204 len: 0 microversion: 1.6'
2019-03-09 17:01:22.060543 | ubuntu-xenial | b'2019-03-09 17:01:19,690 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/74dcdd80-1057-4aef-9cfd-e4014af28b8e" status: 200 len: 459 microversion: 1.0'
2019-03-09 17:01:22.060675 | ubuntu-xenial | b'2019-03-09 17:01:19,709 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/74dcdd80-1057-4aef-9cfd-e4014af28b8e/traits" status: 200 len: 93 microversion: 1.6'
2019-03-09 17:01:22.060812 | ubuntu-xenial | b'2019-03-09 17:01:19,823 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers" status: 202 len: 480 microversion: 2.72 time: 0.110436'
2019-03-09 17:01:22.060965 | ubuntu-xenial | b'2019-03-09 17:01:19,851 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/b6655647-658e-412d-89cb-33b61e731bcc" status: 200 len: 1846 microversion: 2.72 time: 0.023979'
2019-03-09 17:01:22.061266 | ubuntu-xenial | b'2019-03-09 17:01:19,966 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&required1=CUSTOM_PHYSNET2%2CCUSTOM_VNIC_TYPE_NORMAL&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1&resources1=NET_BW_EGR_KILOBIT_PER_SEC%3A1000%2CNET_BW_IGR_KILOBIT_PER_SEC%3A1000" status: 200 len: 2510 microversion: 1.29'
2019-03-09 17:01:22.061421 | ubuntu-xenial | b'2019-03-09 17:01:20,006 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/b6655647-658e-412d-89cb-33b61e731bcc" status: 200 len: 19 microversion: 1.28'
2019-03-09 17:01:22.061564 | ubuntu-xenial | b'2019-03-09 17:01:20,043 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/b6655647-658e-412d-89cb-33b61e731bcc" status: 204 len: 0 microversion: 1.29'
2019-03-09 17:01:22.061692 | ubuntu-xenial | b'2019-03-09 17:01:20,136 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/b6655647-658e-412d-89cb-33b61e731bcc" status: 200 len: 376 microversion: 1.28'
2019-03-09 17:01:22.061829 | ubuntu-xenial | b'2019-03-09 17:01:20,146 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/e409c184-d60f-4770-a8b0-5a40b50f1b1c/traits" status: 200 len: 93 microversion: 1.6'
2019-03-09 17:01:22.062005 | ubuntu-xenial | b'2019-03-09 17:01:20,157 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/0e59ca49-7858-479c-8b7c-13a78199a981/traits" status: 200 len: 235 microversion: 1.6'
2019-03-09 17:01:22.062102 | ubuntu-xenial | b'2019-03-09 17:01:20,308 INFO [nova.compute.claims] Attempting claim on node host1: memory 512 MB, disk 1 GB, vcpus 1 CPU'
2019-03-09 17:01:22.062202 | ubuntu-xenial | b'2019-03-09 17:01:20,309 INFO [nova.compute.claims] Total memory: 8192 MB, used: 512.00 MB'
2019-03-09 17:01:22.062307 | ubuntu-xenial | b'2019-03-09 17:01:20,309 INFO [nova.compute.claims] memory limit not specified, defaulting to unlimited'
2019-03-09 17:01:22.062388 | ubuntu-xenial | b'2019-03-09 17:01:20,310 INFO [nova.compute.claims] Total disk: 1028 GB, used: 0.00 GB'
2019-03-09 17:01:22.062473 | ubuntu-xenial | b'2019-03-09 17:01:20,310 INFO [nova.compute.claims] disk limit not specified, defaulting to unlimited'
2019-03-09 17:01:22.062546 | ubuntu-xenial | b'2019-03-09 17:01:20,310 INFO [nova.compute.claims] Total vcpu: 2 VCPU, used: 0.00 VCPU'
2019-03-09 17:01:22.062629 | ubuntu-xenial | b'2019-03-09 17:01:20,311 INFO [nova.compute.claims] vcpu limit not specified, defaulting to unlimited'
2019-03-09 17:01:22.062699 | ubuntu-xenial | b'2019-03-09 17:01:20,311 INFO [nova.compute.claims] Claim successful on node host1'
2019-03-09 17:01:22.062855 | ubuntu-xenial | b'2019-03-09 17:01:20,632 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/b6655647-658e-412d-89cb-33b61e731bcc" status: 200 len: 1923 microversion: 2.72 time: 0.236979'
2019-03-09 17:01:22.063000 | ubuntu-xenial | b'2019-03-09 17:01:20,655 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/b6655647-658e-412d-89cb-33b61e731bcc" status: 200 len: 376 microversion: 1.28'
2019-03-09 17:01:22.063096 | ubuntu-xenial | b'2019-03-09 17:01:20,715 INFO [nova.compute.manager] Took 0.00 seconds to spawn the instance on the hypervisor.'
2019-03-09 17:01:22.063172 | ubuntu-xenial | b'2019-03-09 17:01:20,783 INFO [nova.compute.manager] Took 0.49 seconds to build instance.'
2019-03-09 17:01:22.063291 | ubuntu-xenial | b"2019-03-09 17:01:20,831 INFO [nova.scheduler.host_manager] Received an update from an unknown host 'host1'. Re-created its InstanceList."
2019-03-09 17:01:22.063451 | ubuntu-xenial | b'2019-03-09 17:01:21,234 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/b6655647-658e-412d-89cb-33b61e731bcc" status: 200 len: 2203 microversion: 2.72 time: 0.096455'
2019-03-09 17:01:22.063575 | ubuntu-xenial | b'2019-03-09 17:01:21,246 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/b6655647-658e-412d-89cb-33b61e731bcc" status: 200 len: 280 microversion: 1.0'
2019-03-09 17:01:22.063758 | ubuntu-xenial | b'2019-03-09 17:01:21,304 INFO [nova.api.openstack.requestlog] 127.0.0.1 "DELETE /v2.1/6f70656e737461636b20342065766572/servers/b6655647-658e-412d-89cb-33b61e731bcc/os-interface/2f2613ce-95a9-490a-b3c4-5f1c28c1f886" status: 202 len: 0 microversion: 2.72 time: 0.054990'
2019-03-09 17:01:22.063911 | ubuntu-xenial | b'2019-03-09 17:01:21,406 INFO [nova.network.neutronv2.api] Port 2f2613ce-95a9-490a-b3c4-5f1c28c1f886 from network info_cache is no longer associated with instance in Neutron. Removing from network info_cache.'
2019-03-09 17:01:22.064059 | ubuntu-xenial | b'2019-03-09 17:01:21,859 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/b6655647-658e-412d-89cb-33b61e731bcc" status: 200 len: 376 microversion: 1.28'
2019-03-09 17:01:22.064188 | ubuntu-xenial | b'2019-03-09 17:01:21,877 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/b6655647-658e-412d-89cb-33b61e731bcc" status: 200 len: 280 microversion: 1.0'
2019-03-09 17:01:22.064325 | ubuntu-xenial | b'2019-03-09 17:01:21,897 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/b6655647-658e-412d-89cb-33b61e731bcc" status: 204 len: 0 microversion: 1.28'
2019-03-09 17:01:22.064413 | ubuntu-xenial | b'2019-03-09 17:01:22,019 INFO [oslo_db.sqlalchemy.provision] DROP ALL OBJECTS, BACKEND sqlite://'
2019-03-09 17:01:22.064492 | ubuntu-xenial | b'2019-03-09 17:01:22,040 INFO [oslo_db.sqlalchemy.provision] DISPOSE ENGINE Engine(sqlite://)'
2019-03-09 17:01:22.064514 | ubuntu-xenial | b''
2019-03-09 17:01:22.064554 | ubuntu-xenial |
2019-03-09 17:01:22.064589 | ubuntu-xenial | Captured traceback:
2019-03-09 17:01:22.064635 | ubuntu-xenial | ~~~~~~~~~~~~~~~~~~~
2019-03-09 17:01:22.064684 | ubuntu-xenial | b'Traceback (most recent call last):'
2019-03-09 17:01:22.064816 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/nova/tests/functional/test_servers.py", line 6478, in test_interface_detach_with_port_with_bandwidth_request'
2019-03-09 17:01:22.064895 | ubuntu-xenial | b' self.assertEqual(1, len(allocations))'
2019-03-09 17:01:22.065016 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional-py35/lib/python3.5/site-packages/testtools/testcase.py", line 411, in assertEqual'
2019-03-09 17:01:22.065068 | ubuntu-xenial | b' self.assertThat(observed, matcher, message)'
2019-03-09 17:01:22.065181 | ubuntu-xenial | b' File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional-py35/lib/python3.5/site-packages/testtools/testcase.py", line 498, in assertThat'
2019-03-09 17:01:22.065218 | ubuntu-xenial | b' raise mismatch_error'
2019-03-09 17:01:22.065299 | ubuntu-xenial | b'testtools.matchers._impl.MismatchError: 1 != 2'
2019-03-09 17:01:22.065331 | ubuntu-xenial | b''

Looks like the test is racing with a port detach cleaning up the vif entry from the network info cache:

2019-03-09 17:01:22.063911 | ubuntu-xenial | b'2019-03-09 17:01:21,406 INFO [nova.network.neutronv2.api] Port 2f2613ce-95a9-490a-b3c4-5f1c28c1f886 from network info_cache is no longer associated with instance in Neutron. Removing from network info_cache.'

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22Port%5C%22%20AND%20message%3A%5C%22from%20network%20info_cache%20is%20no%20longer%20associated%20with%20instance%20in%20Neutron.%20Removing%20from%20network%20info_cache.'%5C%22%20AND%20tags%3A%5C%22console%5C%22&from=7d

18 hits in 7 days, check and gate, all failures.

Balazs Gibizer (balazs-gibizer)
Changed in nova:
assignee: nobody → Balazs Gibizer (balazs-gibizer)
Revision history for this message
Balazs Gibizer (balazs-gibizer) wrote :

@Matt: your observation seems correct. During the deallocate_port_for_instance() call the _unbind_ports() call[1] removes the information from the binding:profile but the allocation only removed from placement after deallocate_port_for_instance() so waiting for the binding:profile cleanup in the test can case the race.

Fortunately interface_detach.end notification emitted after deallocate_port_for_instance() so the test can wait for the notification instead.

[1] https://github.com/openstack/nova/blob/d3d6229b52e484ac7140ad3db451e159c26ad03b/nova/network/neutronv2/api.py#L1730

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (master)

Fix proposed to branch: master
Review: https://review.openstack.org/642387

Changed in nova:
status: Confirmed → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (master)

Reviewed: https://review.openstack.org/642387
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=d52c8fea06e333c9cda42eb60925a112203fc83a
Submitter: Zuul
Branch: master

commit d52c8fea06e333c9cda42eb60925a112203fc83a
Author: Balazs Gibizer <email address hidden>
Date: Mon Mar 11 10:05:02 2019 +0100

    fix race in test_interface_detach_with_port_with_bandwidth_request

    During port detach the unbind towards neutron happens before the
    port allocation is removed from placement. The functional test only
    waited for the port unbind before asserted the remaining allocations and
    therefore it was racy.

    Fortunately the instance.interface_detach.end is emitted after the both
    the unbind and the allocation shrink. So the test is changed to wait for
    this notification instead.

    Change-Id: I53d76d6353ae634e387672e14943f518955b221e
    Closes-Bug: #1819374

Changed in nova:
status: In Progress → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/nova 19.0.0.0rc1

This issue was fixed in the openstack/nova 19.0.0.0rc1 release candidate.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.