Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1710038

Summary:

[RHOS 15] Tempest test failure: test_iscsi_volume

Product:

Red Hat OpenStack

Reporter:

Archit Modi <amodi>

Component:

openstack-neutron

Assignee:

Assaf Muller <amuller>

Status:

CLOSED DUPLICATE

QA Contact:

Roee Agiman <ragiman>

Severity:

unspecified

Docs Contact:

Priority:

unspecified

Version:

15.0 (Stein)

CC:

amuller, chrisw, dasmith, eglynn, jhakimra, jlibosva, kchamart, lyarwood, mbooth, njohnston, sbauza, scohen, sgordon, vromanso

Target Milestone:

---

Target Release:

---

Hardware:

Unspecified

OS:

Unspecified

Whiteboard:

Fixed In Version:

Doc Type:

If docs needed, set a value

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

2019-07-02 13:46:27 UTC

Type:

Bug

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

---

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Embargoed:

Attachments:

Description	Flags
tempest-run.log	none

Description Archit Modi 2019-05-14 19:27:10 UTC

Created attachment 1568623 [details]
tempest-run.log

Description of problem: Run tempest test after deploying RHOS 15 with 1 controller and 2 computes
tempest.api.compute.admin.test_live_migration.LiveAutoBlockMigrationV225Test.test_iscsi_volume

core_puddle: RHOS_TRUNK-15.0-RHEL-8-20190509.n.1

How reproducible: always

Topology: 1 Controller, 2 Compute

Steps to Reproduce:
1. Deploy rhos-15 with 1 controller, 2 compute
2. Run tempest test tempest.api.compute.admin.test_live_migration.LiveAutoBlockMigrationV225Test.test_iscsi_volume
Actual results:
Response - Headers: {'date': 'Sat, 11 May 2019 21:12:50 GMT', 'server': 'Apache', 'content-length': '1222', 'x-compute-request-id': 'req-06cd2093-1ef8-47a4-a40e-80c3e6d82316', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version,Accept-Encoding', 'x-openstack-request-id': 'req-06cd2093-1ef8-47a4-a40e-80c3e6d82316', 'connection': 'close', 'content-type': 'application/json', 'status': '200', 'content-location': 'http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d'}
        Body: b'{"volume": {"id": "de83f166-b721-4ab4-9235-51df0596c13d", "status": "in-use", "size": 1, "availability_zone": "nova", "created_at": "2019-05-11T21:02:37.000000", "updated_at": "2019-05-11T21:08:22.000000", "attachments": [{"id": "de83f166-b721-4ab4-9235-51df0596c13d", "attachment_id": "0fb7dd8b-5e19-4ccb-80a7-37f0e7456630", "volume_id": "de83f166-b721-4ab4-9235-51df0596c13d", "server_id": "36b3b0d2-2e88-4258-807e-93b954ca2214", "host_name": "compute-0.localdomain", "device": "/dev/vdb", "attached_at": "2019-05-11T21:02:46.000000"}], "name": "tempest-LiveAutoBlockMigrationV225Test-volume-37828630", "description": null, "volume_type": "tripleo", "snapshot_id": null, "source_volid": null, "metadata": {}, "links": [{"rel": "self", "href": "http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}, {"rel": "bookmark", "href": "http://10.0.0.137:8776/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}], "user_id": "86dbc929ef1140ca93f3c6bb9479ad67", "bootable": "false", "encrypted": false, "replication_status": null, "consistencygroup_id": null, "multiattach": false, "os-vol-tenant-attr:tenant_id": "d6fb31a901cd4ce5beadf4f25078c32f"}}'
2019-05-11 21:12:52,087 215818 INFO     [tempest.lib.common.rest_client] Request (LiveAutoBlockMigrationV225Test:_run_cleanups): 200 GET http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d 0.173s
2019-05-11 21:12:52,087 215818 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Sat, 11 May 2019 21:12:51 GMT', 'server': 'Apache', 'content-length': '1222', 'x-compute-request-id': 'req-2220b2dc-a0a1-4d6f-8a0e-1a7c317c7698', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version,Accept-Encoding', 'x-openstack-request-id': 'req-2220b2dc-a0a1-4d6f-8a0e-1a7c317c7698', 'connection': 'close', 'content-type': 'application/json', 'status': '200', 'content-location': 'http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d'}
        Body: b'{"volume": {"id": "de83f166-b721-4ab4-9235-51df0596c13d", "status": "in-use", "size": 1, "availability_zone": "nova", "created_at": "2019-05-11T21:02:37.000000", "updated_at": "2019-05-11T21:08:22.000000", "attachments": [{"id": "de83f166-b721-4ab4-9235-51df0596c13d", "attachment_id": "0fb7dd8b-5e19-4ccb-80a7-37f0e7456630", "volume_id": "de83f166-b721-4ab4-9235-51df0596c13d", "server_id": "36b3b0d2-2e88-4258-807e-93b954ca2214", "host_name": "compute-0.localdomain", "device": "/dev/vdb", "attached_at": "2019-05-11T21:02:46.000000"}], "name": "tempest-LiveAutoBlockMigrationV225Test-volume-37828630", "description": null, "volume_type": "tripleo", "snapshot_id": null, "source_volid": null, "metadata": {}, "links": [{"rel": "self", "href": "http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}, {"rel": "bookmark", "href": "http://10.0.0.137:8776/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}], "user_id": "86dbc929ef1140ca93f3c6bb9479ad67", "bootable": "false", "encrypted": false, "replication_status": null, "consistencygroup_id": null, "multiattach": false, "os-vol-tenant-attr:tenant_id": "d6fb31a901cd4ce5beadf4f25078c32f"}}'
2019-05-11 21:12:53,214 215818 INFO     [tempest.lib.common.rest_client] Request (LiveAutoBlockMigrationV225Test:_run_cleanups): 200 GET http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d 0.125s
2019-05-11 21:12:53,215 215818 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Sat, 11 May 2019 21:12:53 GMT', 'server': 'Apache', 'content-length': '1222', 'x-compute-request-id': 'req-5b783984-480f-41e2-adf6-772c7a5c3982', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version,Accept-Encoding', 'x-openstack-request-id': 'req-5b783984-480f-41e2-adf6-772c7a5c3982', 'connection': 'close', 'content-type': 'application/json', 'status': '200', 'content-location': 'http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d'}
        Body: b'{"volume": {"id": "de83f166-b721-4ab4-9235-51df0596c13d", "status": "in-use", "size": 1, "availability_zone": "nova", "created_at": "2019-05-11T21:02:37.000000", "updated_at": "2019-05-11T21:08:22.000000", "attachments": [{"id": "de83f166-b721-4ab4-9235-51df0596c13d", "attachment_id": "0fb7dd8b-5e19-4ccb-80a7-37f0e7456630", "volume_id": "de83f166-b721-4ab4-9235-51df0596c13d", "server_id": "36b3b0d2-2e88-4258-807e-93b954ca2214", "host_name": "compute-0.localdomain", "device": "/dev/vdb", "attached_at": "2019-05-11T21:02:46.000000"}], "name": "tempest-LiveAutoBlockMigrationV225Test-volume-37828630", "description": null, "volume_type": "tripleo", "snapshot_id": null, "source_volid": null, "metadata": {}, "links": [{"rel": "self", "href": "http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}, {"rel": "bookmark", "href": "http://10.0.0.137:8776/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}], "user_id": "86dbc929ef1140ca93f3c6bb9479ad67", "bootable": "false", "encrypted": false, "replication_status": null, "consistencygroup_id": null, "multiattach": false, "os-vol-tenant-attr:tenant_id": "d6fb31a901cd4ce5beadf4f25078c32f"}}'
2019-05-11 21:12:54,523 215818 INFO     [tempest.lib.common.rest_client] Request (LiveAutoBlockMigrationV225Test:_run_cleanups): 200 GET http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d 0.306s
2019-05-11 21:12:54,523 215818 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Sat, 11 May 2019 21:12:54 GMT', 'server': 'Apache', 'content-length': '1222', 'x-compute-request-id': 'req-967b3a6b-e113-4622-9986-8e1e6dbd84eb', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version,Accept-Encoding', 'x-openstack-request-id': 'req-967b3a6b-e113-4622-9986-8e1e6dbd84eb', 'connection': 'close', 'content-type': 'application/json', 'status': '200', 'content-location': 'http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d'}
        Body: b'{"volume": {"id": "de83f166-b721-4ab4-9235-51df0596c13d", "status": "in-use", "size": 1, "availability_zone": "nova", "created_at": "2019-05-11T21:02:37.000000", "updated_at": "2019-05-11T21:08:22.000000", "attachments": [{"id": "de83f166-b721-4ab4-9235-51df0596c13d", "attachment_id": "0fb7dd8b-5e19-4ccb-80a7-37f0e7456630", "volume_id": "de83f166-b721-4ab4-9235-51df0596c13d", "server_id": "36b3b0d2-2e88-4258-807e-93b954ca2214", "host_name": "compute-0.localdomain", "device": "/dev/vdb", "attached_at": "2019-05-11T21:02:46.000000"}], "name": "tempest-LiveAutoBlockMigrationV225Test-volume-37828630", "description": null, "volume_type": "tripleo", "snapshot_id": null, "source_volid": null, "metadata": {}, "links": [{"rel": "self", "href": "http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}, {"rel": "bookmark", "href": "http://10.0.0.137:8776/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}], "user_id": "86dbc929ef1140ca93f3c6bb9479ad67", "bootable": "false", "encrypted": false, "replication_status": null, "consistencygroup_id": null, "multiattach": false, "os-vol-tenant-attr:tenant_id": "d6fb31a901cd4ce5beadf4f25078c32f"}}'
2019-05-11 21:12:55,734 215818 INFO     [tempest.lib.common.rest_client] Request (LiveAutoBlockMigrationV225Test:_run_cleanups): 200 GET http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d 0.209s
2019-05-11 21:12:55,734 215818 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Sat, 11 May 2019 21:12:55 GMT', 'server': 'Apache', 'content-length': '1222', 'x-compute-request-id': 'req-dbfc9044-8ad0-434f-af5f-c99ad26e8e90', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version,Accept-Encoding', 'x-openstack-request-id': 'req-dbfc9044-8ad0-434f-af5f-c99ad26e8e90', 'connection': 'close', 'content-type': 'application/json', 'status': '200', 'content-location': 'http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d'}
        Body: b'{"volume": {"id": "de83f166-b721-4ab4-9235-51df0596c13d", "status": "in-use", "size": 1, "availability_zone": "nova", "created_at": "2019-05-11T21:02:37.000000", "updated_at": "2019-05-11T21:08:22.000000", "attachments": [{"id": "de83f166-b721-4ab4-9235-51df0596c13d", "attachment_id": "0fb7dd8b-5e19-4ccb-80a7-37f0e7456630", "volume_id": "de83f166-b721-4ab4-9235-51df0596c13d", "server_id": "36b3b0d2-2e88-4258-807e-93b954ca2214", "host_name": "compute-0.localdomain", "device": "/dev/vdb", "attached_at": "2019-05-11T21:02:46.000000"}], "name": "tempest-LiveAutoBlockMigrationV225Test-volume-37828630", "description": null, "volume_type": "tripleo", "snapshot_id": null, "source_volid": null, "metadata": {}, "links": [{"rel": "self", "href": "http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}, {"rel": "bookmark", "href": "http://10.0.0.137:8776/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}], "user_id": "86dbc929ef1140ca93f3c6bb9479ad67", "bootable": "false", "encrypted": false, "replication_status": null, "consistencygroup_id": null, "multiattach": false, "os-vol-tenant-attr:tenant_id": "d6fb31a901cd4ce5beadf4f25078c32f"}}'
2019-05-11 21:12:56,865 215818 INFO     [tempest.lib.common.rest_client] Request (LiveAutoBlockMigrationV225Test:_run_cleanups): 200 GET http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d 0.128s
2019-05-11 21:12:56,865 215818 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Sat, 11 May 2019 21:12:56 GMT', 'server': 'Apache', 'content-length': '1222', 'x-compute-request-id': 'req-07b6d7c4-2aba-4c91-b20d-2c7b78cf7911', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version,Accept-Encoding', 'x-openstack-request-id': 'req-07b6d7c4-2aba-4c91-b20d-2c7b78cf7911', 'connection': 'close', 'content-type': 'application/json', 'status': '200', 'content-location': 'http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d'}
        Body: b'{"volume": {"id": "de83f166-b721-4ab4-9235-51df0596c13d", "status": "in-use", "size": 1, "availability_zone": "nova", "created_at": "2019-05-11T21:02:37.000000", "updated_at": "2019-05-11T21:08:22.000000", "attachments": [{"id": "de83f166-b721-4ab4-9235-51df0596c13d", "attachment_id": "0fb7dd8b-5e19-4ccb-80a7-37f0e7456630", "volume_id": "de83f166-b721-4ab4-9235-51df0596c13d", "server_id": "36b3b0d2-2e88-4258-807e-93b954ca2214", "host_name": "compute-0.localdomain", "device": "/dev/vdb", "attached_at": "2019-05-11T21:02:46.000000"}], "name": "tempest-LiveAutoBlockMigrationV225Test-volume-37828630", "description": null, "volume_type": "tripleo", "snapshot_id": null, "source_volid": null, "metadata": {}, "links": [{"rel": "self", "href": "http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}, {"rel": "bookmark", "href": "http://10.0.0.137:8776/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}], "user_id": "86dbc929ef1140ca93f3c6bb9479ad67", "bootable": "false", "encrypted": false, "replication_status": null, "consistencygroup_id": null, "multiattach": false, "os-vol-tenant-attr:tenant_id": "d6fb31a901cd4ce5beadf4f25078c32f"}}'
2019-05-11 21:12:58,079 215818 INFO     [tempest.lib.common.rest_client] Request (LiveAutoBlockMigrationV225Test:_run_cleanups): 200 GET http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d 0.212s
2019-05-11 21:12:58,079 215818 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Sat, 11 May 2019 21:12:57 GMT', 'server': 'Apache', 'content-length': '1222', 'x-compute-request-id': 'req-218d39a0-db21-48bd-8656-ebf3bb7fb933', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version,Accept-Encoding', 'x-openstack-request-id': 'req-218d39a0-db21-48bd-8656-ebf3bb7fb933', 'connection': 'close', 'content-type': 'application/json', 'status': '200', 'content-location': 'http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d'}
        Body: b'{"volume": {"id": "de83f166-b721-4ab4-9235-51df0596c13d", "status": "in-use", "size": 1, "availability_zone": "nova", "created_at": "2019-05-11T21:02:37.000000", "updated_at": "2019-05-11T21:08:22.000000", "attachments": [{"id": "de83f166-b721-4ab4-9235-51df0596c13d", "attachment_id": "0fb7dd8b-5e19-4ccb-80a7-37f0e7456630", "volume_id": "de83f166-b721-4ab4-9235-51df0596c13d", "server_id": "36b3b0d2-2e88-4258-807e-93b954ca2214", "host_name": "compute-0.localdomain", "device": "/dev/vdb", "attached_at": "2019-05-11T21:02:46.000000"}], "name": "tempest-LiveAutoBlockMigrationV225Test-volume-37828630", "description": null, "volume_type": "tripleo", "snapshot_id": null, "source_volid": null, "metadata": {}, "links": [{"rel": "self", "href": "http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}, {"rel": "bookmark", "href": "http://10.0.0.137:8776/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}], "user_id": "86dbc929ef1140ca93f3c6bb9479ad67", "bootable": "false", "encrypted": false, "replication_status": null, "consistencygroup_id": null, "multiattach": false, "os-vol-tenant-attr:tenant_id": "d6fb31a901cd4ce5beadf4f25078c32f"}}'
2019-05-11 21:12:59,190 215818 INFO     [tempest.lib.common.rest_client] Request (LiveAutoBlockMigrationV225Test:_run_cleanups): 200 GET http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d 0.109s
2019-05-11 21:12:59,190 215818 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Sat, 11 May 2019 21:12:59 GMT', 'server': 'Apache', 'content-length': '1222', 'x-compute-request-id': 'req-0fef1bee-8b61-42b7-9435-02298b6352fb', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version,Accept-Encoding', 'x-openstack-request-id': 'req-0fef1bee-8b61-42b7-9435-02298b6352fb', 'connection': 'close', 'content-type': 'application/json', 'status': '200', 'content-location': 'http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d'}
        Body: b'{"volume": {"id": "de83f166-b721-4ab4-9235-51df0596c13d", "status": "in-use", "size": 1, "availability_zone": "nova", "created_at": "2019-05-11T21:02:37.000000", "updated_at": "2019-05-11T21:08:22.000000", "attachments": [{"id": "de83f166-b721-4ab4-9235-51df0596c13d", "attachment_id": "0fb7dd8b-5e19-4ccb-80a7-37f0e7456630", "volume_id": "de83f166-b721-4ab4-9235-51df0596c13d", "server_id": "36b3b0d2-2e88-4258-807e-93b954ca2214", "host_name": "compute-0.localdomain", "device": "/dev/vdb", "attached_at": "2019-05-11T21:02:46.000000"}], "name": "tempest-LiveAutoBlockMigrationV225Test-volume-37828630", "description": null, "volume_type": "tripleo", "snapshot_id": null, "source_volid": null, "metadata": {}, "links": [{"rel": "self", "href": "http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}, {"rel": "bookmark", "href": "http://10.0.0.137:8776/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}], "user_id": "86dbc929ef1140ca93f3c6bb9479ad67", "bootable": "false", "encrypted": false, "replication_status": null, "consistencygroup_id": null, "multiattach": false, "os-vol-tenant-attr:tenant_id": "d6fb31a901cd4ce5beadf4f25078c32f"}}'
2019-05-11 21:13:00,286 215818 INFO     [tempest.lib.common.rest_client] Request (LiveAutoBlockMigrationV225Test:_run_cleanups): 200 GET http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d 0.094s
2019-05-11 21:13:00,287 215818 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Sat, 11 May 2019 21:13:00 GMT', 'server': 'Apache', 'content-length': '1222', 'x-compute-request-id': 'req-26bc665e-f492-493d-b8fb-ab51e198d07f', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version,Accept-Encoding', 'x-openstack-request-id': 'req-26bc665e-f492-493d-b8fb-ab51e198d07f', 'connection': 'close', 'content-type': 'application/json', 'status': '200', 'content-location': 'http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d'}
        Body: b'{"volume": {"id": "de83f166-b721-4ab4-9235-51df0596c13d", "status": "in-use", "size": 1, "availability_zone": "nova", "created_at": "2019-05-11T21:02:37.000000", "updated_at": "2019-05-11T21:08:22.000000", "attachments": [{"id": "de83f166-b721-4ab4-9235-51df0596c13d", "attachment_id": "0fb7dd8b-5e19-4ccb-80a7-37f0e7456630", "volume_id": "de83f166-b721-4ab4-9235-51df0596c13d", "server_id": "36b3b0d2-2e88-4258-807e-93b954ca2214", "host_name": "compute-0.localdomain", "device": "/dev/vdb", "attached_at": "2019-05-11T21:02:46.000000"}], "name": "tempest-LiveAutoBlockMigrationV225Test-volume-37828630", "description": null, "volume_type": "tripleo", "snapshot_id": null, "source_volid": null, "metadata": {}, "links": [{"rel": "self", "href": "http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}, {"rel": "bookmark", "href": "http://10.0.0.137:8776/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}], "user_id": "86dbc929ef1140ca93f3c6bb9479ad67", "bootable": "false", "encrypted": false, "replication_status": null, "consistencygroup_id": null, "multiattach": false, "os-vol-tenant-attr:tenant_id": "d6fb31a901cd4ce5beadf4f25078c32f"}}'
2019-05-11 21:13:01,391 215818 INFO     [tempest.lib.common.rest_client] Request (LiveAutoBlockMigrationV225Test:_run_cleanups): 200 GET http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d 0.103s
2019-05-11 21:13:01,392 215818 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Sat, 11 May 2019 21:13:01 GMT', 'server': 'Apache', 'content-length': '1222', 'x-compute-request-id': 'req-60b8b0ec-b6e0-4b94-8ea9-ba89e1753458', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version,Accept-Encoding', 'x-openstack-request-id': 'req-60b8b0ec-b6e0-4b94-8ea9-ba89e1753458', 'connection': 'close', 'content-type': 'application/json', 'status': '200', 'content-location': 'http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d'}
        Body: b'{"volume": {"id": "de83f166-b721-4ab4-9235-51df0596c13d", "status": "in-use", "size": 1, "availability_zone": "nova", "created_at": "2019-05-11T21:02:37.000000", "updated_at": "2019-05-11T21:08:22.000000", "attachments": [{"id": "de83f166-b721-4ab4-9235-51df0596c13d", "attachment_id": "0fb7dd8b-5e19-4ccb-80a7-37f0e7456630", "volume_id": "de83f166-b721-4ab4-9235-51df0596c13d", "server_id": "36b3b0d2-2e88-4258-807e-93b954ca2214", "host_name": "compute-0.localdomain", "device": "/dev/vdb", "attached_at": "2019-05-11T21:02:46.000000"}], "name": "tempest-LiveAutoBlockMigrationV225Test-volume-37828630", "description": null, "volume_type": "tripleo", "snapshot_id": null, "source_volid": null, "metadata": {}, "links": [{"rel": "self", "href": "http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}, {"rel": "bookmark", "href": "http://10.0.0.137:8776/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}], "user_id": "86dbc929ef1140ca93f3c6bb9479ad67", "bootable": "false", "encrypted": false, "replication_status": null, "consistencygroup_id": null, "multiattach": false, "os-vol-tenant-attr:tenant_id": "d6fb31a901cd4ce5beadf4f25078c32f"}}'
2019-05-11 21:13:02,526 215818 INFO     [tempest.lib.common.rest_client] Request (LiveAutoBlockMigrationV225Test:_run_cleanups): 200 GET http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d 0.133s
2019-05-11 21:13:02,527 215818 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Sat, 11 May 2019 21:13:02 GMT', 'server': 'Apache', 'content-length': '1222', 'x-compute-request-id': 'req-5d222c67-dc2e-4798-901f-d0d1726f2b25', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version,Accept-Encoding', 'x-openstack-request-id': 'req-5d222c67-dc2e-4798-901f-d0d1726f2b25', 'connection': 'close', 'content-type': 'application/json', 'status': '200', 'content-location': 'http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d'}
        Body: b'{"volume": {"id": "de83f166-b721-4ab4-9235-51df0596c13d", "status": "in-use", "size": 1, "availability_zone": "nova", "created_at": "2019-05-11T21:02:37.000000", "updated_at": "2019-05-11T21:08:22.000000", "attachments": [{"id": "de83f166-b721-4ab4-9235-51df0596c13d", "attachment_id": "0fb7dd8b-5e19-4ccb-80a7-37f0e7456630", "volume_id": "de83f166-b721-4ab4-9235-51df0596c13d", "server_id": "36b3b0d2-2e88-4258-807e-93b954ca2214", "host_name": "compute-0.localdomain", "device": "/dev/vdb", "attached_at": "2019-05-11T21:02:46.000000"}], "name": "tempest-LiveAutoBlockMigrationV225Test-volume-37828630", "description": null, "volume_type": "tripleo", "snapshot_id": null, "source_volid": null, "metadata": {}, "links": [{"rel": "self", "href": "http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}, {"rel": "bookmark", "href": "http://10.0.0.137:8776/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}], "user_id": "86dbc929ef1140ca93f3c6bb9479ad67", "bootable": "false", "encrypted": false, "replication_status": null, "consistencygroup_id": null, "multiattach": false, "os-vol-tenant-attr:tenant_id": "d6fb31a901cd4ce5beadf4f25078c32f"}}'
2019-05-11 21:13:04,038 215818 INFO     [tempest.lib.common.rest_client] Request (LiveAutoBlockMigrationV225Test:_run_cleanups): 200 GET http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d 0.510s
2019-05-11 21:13:04,039 215818 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: None
    Response - Headers: {'date': 'Sat, 11 May 2019 21:13:03 GMT', 'server': 'Apache', 'content-length': '1222', 'x-compute-request-id': 'req-1417f233-0e3f-4926-997d-96b642ef71ef', 'openstack-api-version': 'volume 3.0', 'vary': 'OpenStack-API-Version,Accept-Encoding', 'x-openstack-request-id': 'req-1417f233-0e3f-4926-997d-96b642ef71ef', 'connection': 'close', 'content-type': 'application/json', 'status': '200', 'content-location': 'http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d'}
        Body: b'{"volume": {"id": "de83f166-b721-4ab4-9235-51df0596c13d", "status": "in-use", "size": 1, "availability_zone": "nova", "created_at": "2019-05-11T21:02:37.000000", "updated_at": "2019-05-11T21:08:22.000000", "attachments": [{"id": "de83f166-b721-4ab4-9235-51df0596c13d", "attachment_id": "0fb7dd8b-5e19-4ccb-80a7-37f0e7456630", "volume_id": "de83f166-b721-4ab4-9235-51df0596c13d", "server_id": "36b3b0d2-2e88-4258-807e-93b954ca2214", "host_name": "compute-0.localdomain", "device": "/dev/vdb", "attached_at": "2019-05-11T21:02:46.000000"}], "name": "tempest-LiveAutoBlockMigrationV225Test-volume-37828630", "description": null, "volume_type": "tripleo", "snapshot_id": null, "source_volid": null, "metadata": {}, "links": [{"rel": "self", "href": "http://10.0.0.137:8776/v3/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}, {"rel": "bookmark", "href": "http://10.0.0.137:8776/d6fb31a901cd4ce5beadf4f25078c32f/volumes/de83f166-b721-4ab4-9235-51df0596c13d"}], "user_id": "86dbc929ef1140ca93f3c6bb9479ad67", "bootable": "false", "encrypted": false, "replication_status": null, "consistencygroup_id": null, "multiattach": false, "os-vol-tenant-attr:tenant_id": "d6fb31a901cd4ce5beadf4f25078c32f"}}'
}}}

traceback-1: {{{
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/tempest/api/compute/base.py", line 511, in _detach_volume
    self.servers_client.detach_volume(server['id'], volume['id'])
  File "/usr/lib/python3.6/site-packages/tempest/lib/services/compute/servers_client.py", line 449, in detach_volume
    (server_id, volume_id))
  File "/usr/lib/python3.6/site-packages/tempest/lib/common/rest_client.py", line 314, in delete
    return self.request('DELETE', url, extra_headers, headers, body)
  File "/usr/lib/python3.6/site-packages/tempest/lib/services/compute/base_compute_client.py", line 48, in request
    method, url, extra_headers, headers, body, chunked)
  File "/usr/lib/python3.6/site-packages/tempest/lib/common/rest_client.py", line 679, in request
    self._error_checker(resp, resp_body)
  File "/usr/lib/python3.6/site-packages/tempest/lib/common/rest_client.py", line 800, in _error_checker
    raise exceptions.Conflict(resp_body, resp=resp)
tempest.lib.exceptions.Conflict: Conflict with state of target resource
Details: {'code': 409, 'message': "Cannot 'detach_volume' instance 36b3b0d2-2e88-4258-807e-93b954ca2214 while it is in task_state migrating"}
}}}

traceback-2: {{{
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/tempest/common/waiters.py", line 211, in wait_for_volume_resource_status
    raise lib_exc.TimeoutException(message)
tempest.lib.exceptions.TimeoutException: Request timed out
Details: volume de83f166-b721-4ab4-9235-51df0596c13d failed to reach available status (current in-use) within the required time (300 s).
}}}

Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/tempest/common/utils/__init__.py", line 89, in wrapper
    return f(*func_args, **func_kwargs)
  File "/usr/lib/python3.6/site-packages/tempest/api/compute/admin/test_live_migration.py", line 164, in test_iscsi_volume
    self._live_migrate(server_id, target_host, 'ACTIVE')
  File "/usr/lib/python3.6/site-packages/tempest/api/compute/admin/test_live_migration.py", line 77, in _live_migrate
    waiters.wait_for_server_status(self.servers_client, server_id, state)
  File "/usr/lib/python3.6/site-packages/tempest/common/waiters.py", line 96, in wait_for_server_status
    raise lib_exc.TimeoutException(message)
tempest.lib.exceptions.TimeoutException: Request timed out
Details: (LiveAutoBlockMigrationV225Test:test_iscsi_volume) Server 36b3b0d2-2e88-4258-807e-93b954ca2214 failed to reach ACTIVE status and task state "None" within the required time (300 s). Current status: MIGRATING. Current task state: migrating.

Expected results: Test passed successfully

Additional info:

Comment 2 Archit Modi 2019-05-14 19:34:47 UTC

Also, the following tempest test failed with similar result:
tempest.api.compute.admin.test_live_migration.LiveMigrationTest.test_iscsi_volume

Comment 3 melanie witt 2019-05-17 01:17:00 UTC

Looks like the live migration failed waiting for the 'network-vif-plugged' event from neutron. Found this in the nova-compute.log [1]:

2019-05-11 21:13:42.167 8 WARNING nova.compute.manager [-] [instance: 6038579b-3a31-470f-85b6-8a1a0e4b8a1e] Timed out waiting for events: [('network-vif-plugged', 'a2879b05-2f7a-4b1b-91af-faa91074d654')]. If these timeouts are a persistent issue it could mean the networking backend on host compute-1.localdomain does not support sending these events unless there are port binding host changes which does not happen at this point in the live migration process. You may need to disable the live_migration_wait_for_vif_plug option on host compute-1.localdomain.: eventlet.timeout.Timeout: 300 seconds

13 seconds later, we receive a 'network-changed' event for the instance:

2019-05-11 21:13:55.993 8 DEBUG nova.compute.manager [req-a858db8b-b5a2-47ac-8697-e5115ceeca58 b2444e993ea64c0fb247340e24e26004 eaf60d0147884211a27211f29f21fc31 - default default] [instance: 6038579b-3a31-470f-85b6-8a1a0e4b8a1e] Received event network-changed-a2879b05-2f7a-4b1b-91af-faa91074d654 external_instance_event /usr/lib/python3.6/site-packages/nova/compute/manager.py:8357

Then way later on, when the instance is being deleted, we see this message, repeating that it never received the 'network-vif-plugged' event from neutron:

2019-05-11 21:31:17.814 8 DEBUG nova.compute.manager [req-e067d5dc-323b-4ee9-865e-9bba9d5d3a68 181b6610a53b405a96c5c0fca7bba6fb 646583384be54cfda42f90b6d2dee13a - default default] [instance: 6038579b-3a31-470f-85b6-8a1a0e4b8a1e] Events pending at deletion: network-vif-plugged-a2879b05-2f7a-4b1b-91af-faa91074d654 _delete_instance /usr/lib/python3.6/site-packages/nova/compute/manager.py:2723

[1] http://cougar11.scl.lab.tlv.redhat.com/DFG-compute-nova-15_director-rhel-virthost-1cont_2comp-ipv4-geneve-live-migration/6/compute-0.tar.gz?compute-0/var/log/containers/nova/nova-compute.log

Comment 4 melanie witt 2019-05-17 01:19:46 UTC

Comment 3 ^ was about the tempest.api.compute.admin.test_live_migration.LiveMigrationTest.test_iscsi_volume test failure (sorry, looked at the wrong one).

Comment 5 melanie witt 2019-05-17 01:29:27 UTC

Looks like the same thing happened for tempest.api.compute.admin.test_live_migration.LiveAutoBlockMigrationV225Test.test_iscsi_volume though:

2019-05-11 21:02:59.423 8 DEBUG nova.compute.manager [-] [instance: 36b3b0d2-2e88-4258-807e-93b954ca2214] Preparing to wait for external event network-vif-plugged-ab77e38a-7534-42ee-a268-2be01dad71b3 prepare_for_instance_event /usr/lib/python3.6/site-packages/nova/compute/manager.py:326

2019-05-11 21:08:19.823 8 WARNING nova.compute.manager [-] [instance: 36b3b0d2-2e88-4258-807e-93b954ca2214] Timed out waiting for events: [('network-vif-plugged', 'ab77e38a-7534-42ee-a268-2be01dad71b3')]. If these timeouts are a persistent issue it could mean the networking backend on host compute-1.localdomain does not support sending these events unless there are port binding host changes which does not happen at this point in the live migration process. You may need to disable the live_migration_wait_for_vif_plug option on host compute-1.localdomain.: eventlet.timeout.Timeout: 300 seconds

2019-05-11 21:08:39.050 8 DEBUG nova.compute.manager [req-a7664bed-e9fe-4ab3-84ef-084ffd46744a b2444e993ea64c0fb247340e24e26004 eaf60d0147884211a27211f29f21fc31 - default default] [instance: 36b3b0d2-2e88-4258-807e-93b954ca2214] Received event network-changed-ab77e38a-7534-42ee-a268-2be01dad71b3 external_instance_event /usr/lib/python3.6/site-packages/nova/compute/manager.py:8357

2019-05-11 21:30:01.846 8 DEBUG nova.compute.manager [req-f224c720-f083-46f1-bcb4-4132c8aead1d 86dbc929ef1140ca93f3c6bb9479ad67 d6fb31a901cd4ce5beadf4f25078c32f - default default] [instance: 36b3b0d2-2e88-4258-807e-93b954ca2214] Events pending at deletion: network-vif-plugged-ab77e38a-7534-42ee-a268-2be01dad71b3 _delete_instance /usr/lib/python3.6/site-packages/nova/compute/manager.py:2723

Comment 6 Matthew Booth 2019-05-24 14:25:52 UTC

*** Bug 1710040 has been marked as a duplicate of this bug. ***

Comment 8 Francois Palin 2019-05-24 15:54:57 UTC

*** Bug 1710041 has been marked as a duplicate of this bug. ***

Comment 9 Artom Lifshitz 2019-06-07 02:27:44 UTC

Notes:

Instance: 36b3b0d2-2e88-4258-807e-93b954ca2214
Port:     ab77e38a-7534-42ee-a268-2be01dad71b3

Migration request arrives:

2019-05-11 21:02:50.941 [nova-api.log] 22 DEBUG nova.api.openstack.wsgi
[req-37e395bc-8d99-421c-b54a-32a859d1d3e7 395e67fe8d1b453e9b92f68c07629f3f 64bcce5cac32490db7cf3c5de45d902f - default default]
Action: 'action', calling method: <bound method MigrateServerController._migrate_live of <nova.api.openstack.compute.migrate_server.MigrateServerController object at 0x7ff527ccbfd0>>,
body: {"os-migrateLive": {"host": "compute-1.localdomain", "block_migration": "auto"}}
_process_stack /usr/lib/python3.6/site-packages/nova/api/openstack/wsgi.py:520

Confirmation that live migration will wait for external event:

2019-05-11 21:02:59.468 [compute-1-nova-compute.log] 9 DEBUG nova.compute.manager
[req-37e395bc-8d99-421c-b54a-32a859d1d3e7 395e67fe8d1b453e9b92f68c07629f3f 64bcce5cac32490db7cf3c5de45d902f - default default]
pre_live_migration data is LibvirtLiveMigrateData(bdms=<?>,block_migration=True,disk_available_mb=43008,disk_over_commit=<?>,dst_wants_file_backed_memory=False,file_backed_memory_discard=False,filename='tmp2cpxec4r',graphics_listen_addr_spice=127.0.0.1,graphics_listen_addr_vnc=172.17.1.75,image_type='default',instance_relative_path='36b3b0d2-2e88-4258-807e-93b954ca2214',is_shared_block_storage=False,is_shared_instance_path=False,is_volume_backed=False,migration=<?>,old_vol_attachment_ids=<?>,serial_listen_addr=None,serial_listen_ports=<?>,src_supports_native_luks=True,supported_perf_events=<?>,target_connect_addr=<?>,vifs=[VIFMigrateData],wait_for_vif_plugged=<?>)
pre_live_migration /usr/lib/python3.6/site-packages/nova/compute/manager.py:6278

Preparing to wait for external event during live migration... but on compute-0 (the source!), and *before* pre_live_migration?

2019-05-11 21:02:59.423 [compute-0-nova-compute.log] 8 DEBUG nova.compute.manager [-] [instance: 36b3b0d2-2e88-4258-807e-93b954ca2214]
Preparing to wait for external event network-vif-plugged-ab77e38a-7534-42ee-a268-2be01dad71b3
prepare_for_instance_event /usr/lib/python3.6/site-packages/nova/compute/manager.py:326

Timed out waiting for event:

2019-05-11 21:08:19.823 [compute-0-nova-compute.log] 8 WARNING nova.compute.manager [-] [instance: 36b3b0d2-2e88-4258-807e-93b954ca2214]
Timed out waiting for events: [('network-vif-plugged', 'ab77e38a-7534-42ee-a268-2be01dad71b3')]. If these timeouts are a persistent issue it could mean the networking backend on host compute-1.localdomain does not support sending these events unless there are port binding host changes which does not happen at this point in the live migration process. You may need to disable the live_migration_wait_for_vif_plug option on host compute-1.localdomain.: eventlet.timeout.Timeout: 300 seconds

However, VIF does get plugged on the dest:

2019-05-11 21:03:10.982 [compute-1-nova-compute.log] 9 INFO os_vif [req-37e395bc-8d99-421c-b54a-32a859d1d3e7 395e67fe8d1b453e9b92f68c07629f3f 64bcce5cac32490db7cf3c5de45d902f - default default]
Successfully plugged vif VIFOpenVSwitch(active=False,address=fa:16:3e:f7:e3:26,bridge_name='br-int',has_traffic_filtering=True,id=ab77e38a-7534-42ee-a268-2be01dad71b3,network=Network(448431a2-29b2-4aa4-9080-a65837990cfb),plugin=
'ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tapab77e38a-75')

No mention anywhere of any unexpected event being received, so to answer Matt's question in comment #7, looks like it's 2 - we don't received the event at all. Preparing to wait on the source before pre_live_migration is still weird though.

Comment 10 Artom Lifshitz 2019-06-07 02:34:53 UTC

Ah, look like it's normal to wait for events before calling pre_live_migration: https://github.com/openstack/nova/blob/stable/stein/nova/compute/manager.py#L6525-L6548

We see it finish plm successfully:

2019-05-11 21:03:19.821 [compute-0-nova-compute.log] 8 INFO nova.compute.manager [-] [instance: 36b3b0d2-2e88-4258-807e-93b954ca2214] Took 20.40 seconds for pre_live_migration on destination host compute-1.local
domain.

And no mention of 'Not waiting for events after pre_live_migration' anywhere.

Comment 11 Artom Lifshitz 2019-06-07 03:10:42 UTC

Actually, correction:

There's still a pending event when the instance gets cleaned up:

(Clean up instance delete request from tempest log: 2019-05-11 21:30:01.831 215818 INFO tempest.lib.common.rest_client [req-f224c720-f083-46f1-bcb4-4132c8aead1d ] Request (LiveAutoBlockMigrationV225Test:tearDownClass): 204 DELETE http://10.0.0.137:8774/v2.1/servers/36b3b0d2-2e88-4258-807e-93b954ca2214 0.572s)

2019-05-11 21:30:01.846 [compute-0-nova-compute.log] 8 DEBUG nova.compute.manager [req-f224c720-f083-46f1-bcb4-4132c8aead1d 86dbc929ef1140ca93f3c6bb9479ad67 d6fb31a901cd4ce5beadf4f25078c32f - default default] [instance: 36b3b0d2-2e88-4258-807e-93b954ca2214] Events pending at deletion: network-vif-plugged-ab77e38a-7534-42ee-a268-2be01dad71b3 _delete_instance /usr/lib/python3.6/site-packages/nova/compute/manager.py:2723

And compute-0 does eventually get the vif-plugged event:

2019-05-11 21:30:02.183 [compute-0-nova-compute.log] 8 WARNING nova.compute.manager [req-335e16db-0070-431a-a621-9d0a93858971 b2444e993ea64c0fb247340e24e26004 eaf60d0147884211a27211f29f21fc31 - default default] [instance: 36b3b0d2-2e88-4258-807e-93b954ca2214] Received unexpected event network-vif-plugged-ab77e38a-7534-42ee-a268-2be01dad71b3 for instance with vm_state active and task_state deleting.

Comment 12 Artom Lifshitz 2019-06-07 14:25:13 UTC

*** Bug 1710128 has been marked as a duplicate of this bug. ***

Comment 13 Artom Lifshitz 2019-06-07 14:33:11 UTC

Neutron OVN folks,

I'm passing this bug over to you because I'm hoping you can tell me why the vif-plugged external event takes so long to arrive. A summary of the context:

During a live migration to compute-1, Nova updates the port bindings to the destination host:

2019-05-11 21:02:53.962 [nova-conductor.log] 23 DEBUG nova.conductor.tasks.live_migrate [req-37e395bc-8d99-421c-b54a-32a859d1d3e7 395e67fe8d1b453e9b92f68c07629f3f 64bcce5cac32490db7cf3c5de45d902f - default default] [instance: 36b3b0d2-2e88-4258-807e-93b954ca2214] Start binding ports on destination host: compute-1.localdomain _bind_ports_on_destination /usr/lib/python3.6/site-packages/nova/conductor/tasks/live_migrate.py:288

Nova then prepares to wait for external vif-plugged events relating to that binding update:

2019-05-11 21:02:59.423 [compute-0-nova-compute.log] 8 DEBUG nova.compute.manager [-] [instance: 36b3b0d2-2e88-4258-807e-93b954ca2214] Preparing to wait for external event network-vif-plugged-ab77e38a-7534-42ee-a268-2be01dad71b3 prepare_for_instance_event /usr/lib/python3.6/site-packages/nova/compute/manager.py:326

And os-vif plugs the VIF:

2019-05-11 21:03:10.982 [compute-1-nova-compute.log] 9 INFO os_vif [req-37e395bc-8d99-421c-b54a-32a859d1d3e7 395e67fe8d1b453e9b92f68c07629f3f 64bcce5cac32490db7cf3c5de45d902f - default default] Successfully plugged vif VIFOpenVSwitch(active=False,address=fa:16:3e:f7:e3:26,bridge_name='br-int',has_traffic_filtering=True,id=ab77e38a-7534-42ee-a268-2be01dad71b3,network=Network(448431a2-29b2-4aa4-9080-a65837990cfb),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tapab77e38a-75')

However, Nova eventually times out waiting for the external event:

2019-05-11 21:08:19.823 [compute-0-nova-compute.log] 8 WARNING nova.compute.manager [-] [instance: 36b3b0d2-2e88-4258-807e-93b954ca2214] Timed out waiting for events: [('network-vif-plugged', 'ab77e38a-7534-42ee-a268-2be01dad71b3')]. If these timeouts are a persistent issue it could mean the networking backend on host compute-1.localdomain does not support sending these events unless there are port binding host changes which does not happen at this point in the live migration process. You may need to disable the live_migration_wait_for_vif_plug option on host compute-1.localdomain.: eventlet.timeout.Timeout: 300 seconds

Even though Nova does receive the event, but at a time when it's too late and the instance is already being deleted as part of the Tempest test tearDown:

2019-05-11 21:30:02.183 [compute-0-nova-compute.log] 8 WARNING nova.compute.manager [req-335e16db-0070-431a-a621-9d0a93858971 b2444e993ea64c0fb247340e24e26004 eaf60d0147884211a27211f29f21fc31 - default default] [instance: 36b3b0d2-2e88-4258-807e-93b954ca2214] Received unexpected event network-vif-plugged-ab77e38a-7534-42ee-a268-2be01dad71b3 for instance with vm_state active and task_state deleting.

I'm hoping you can shed some light on why the event takes so long to arrive.

Let me know if you have any questions, I'll help in any way I can.

Thanks!

Comment 14 Artom Lifshitz 2019-06-07 14:35:13 UTC

From a comment [1] in the duplicate bug, this might be the same thing as bz 1642106.

[1] https://bugzilla.redhat.com/show_bug.cgi?id=1710128#c2

Comment 15 Jakub Libosvar 2019-07-02 13:46:27 UTC


*** This bug has been marked as a duplicate of bug 1716335 ***