yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1897796] [NEW] Scenario test test_subport_connectivity failing from time to time

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Slawek Kaplonski <1897796@xxxxxxxxxxxxxxxxxx>
Date: Tue, 29 Sep 2020 20:01:08 -0000
Reply-to: Bug 1897796 <1897796@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

Test
neutron_tempest_plugin.scenario.test_trunk.TrunkTest.test_subport_connectivity
is failing from time to time.

Example of failure:
https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_d30/748367/16/check/neutron-tempest-plugin-scenario-openvswitch-ussuri/d30c240/testr_results.html

Logstash query:
http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22line%20272%2C%20in%20test_subport_connectivity%5C%22

Stacktrace:
2020-09-26 13:34:08,478 32048 INFO     [paramiko.transport] Connected (version 2.0, client OpenSSH_7.2p2)
2020-09-26 13:34:10,019 32048 INFO     [paramiko.transport] Authentication (publickey) successful!
2020-09-26 13:34:10,019 32048 INFO     [tempest.lib.common.ssh] ssh connection to ubuntu@172.24.5.202 successfully created
2020-09-26 13:34:54,698 32048 DEBUG    [neutron_tempest_plugin.common.shell] Command "sudo '/sbin/ip' address list" succeeded:
stderr:
None
stdout:
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: ens3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1400 qdisc pfifo_fast state UP group default qlen 1000
    link/ether fa:16:3e:d8:d8:fb brd ff:ff:ff:ff:ff:ff
    inet 10.1.0.14/28 brd 10.1.0.15 scope global ens3
       valid_lft forever preferred_lft forever
    inet6 fe80::f816:3eff:fed8:d8fb/64 scope link 
       valid_lft forever preferred_lft forever


2020-09-26 13:34:54,699 32048 DEBUG    [neutron_tempest_plugin.common.ip] Device parsed: Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'})
2020-09-26 13:34:54,700 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: Address(family='link/loopback', address='00:00:00:00:00:00', device=Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'}), properties={'brd': '00:00:00:00:00:00'})
2020-09-26 13:34:54,700 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet', address='127.0.0.1/8', device=Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'}), properties={'scope': 'host'})
2020-09-26 13:34:54,701 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'scope': 'host', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
2020-09-26 13:34:54,701 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet6', address='::1/128', device=Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'}), properties={'scope': 'host'})
2020-09-26 13:34:54,702 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'scope': 'host', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
2020-09-26 13:34:54,702 32048 DEBUG    [neutron_tempest_plugin.common.ip] Device parsed: Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'})
2020-09-26 13:34:54,702 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: Address(family='link/ether', address='fa:16:3e:d8:d8:fb', device=Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'}), properties={'brd': 'ff:ff:ff:ff:ff:ff'})
2020-09-26 13:34:54,703 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet', address='10.1.0.14/28', device=Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'}), properties={'brd': '10.1.0.15', 'scope': 'global'})
2020-09-26 13:34:54,703 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'brd': '10.1.0.15', 'scope': 'global', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
2020-09-26 13:34:54,703 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet6', address='fe80::f816:3eff:fed8:d8fb/64', device=Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'}), properties={'scope': 'link'})
2020-09-26 13:34:54,704 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'scope': 'link', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
2020-09-26 13:34:54,706 32048 DEBUG    [neutron_tempest_plugin.common.shell] Executing command "sudo '/sbin/ip' address list" on remote host '172.24.5.202' (timeout=None)...
2020-09-26 13:34:54,706 32048 INFO     [tempest.lib.common.ssh] Creating ssh connection to '172.24.5.202:22' as 'ubuntu' with public key authentication
2020-09-26 13:34:57,146 32048 INFO     [paramiko.transport] Connected (version 2.0, client OpenSSH_7.2p2)
2020-09-26 13:34:58,343 32048 INFO     [paramiko.transport] Authentication (publickey) successful!
2020-09-26 13:34:58,343 32048 INFO     [tempest.lib.common.ssh] ssh connection to ubuntu@172.24.5.202 successfully created
2020-09-26 13:35:34,039 32048 DEBUG    [neutron_tempest_plugin.common.shell] Command "sudo '/sbin/ip' address list" succeeded:
stderr:
None
stdout:
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: ens3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1400 qdisc pfifo_fast state UP group default qlen 1000
    link/ether fa:16:3e:d8:d8:fb brd ff:ff:ff:ff:ff:ff
    inet 10.1.0.14/28 brd 10.1.0.15 scope global ens3
       valid_lft forever preferred_lft forever
    inet6 fe80::f816:3eff:fed8:d8fb/64 scope link 
       valid_lft forever preferred_lft forever


2020-09-26 13:35:34,040 32048 DEBUG    [neutron_tempest_plugin.common.ip] Device parsed: Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'})
2020-09-26 13:35:34,040 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: Address(family='link/loopback', address='00:00:00:00:00:00', device=Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'}), properties={'brd': '00:00:00:00:00:00'})
2020-09-26 13:35:34,040 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet', address='127.0.0.1/8', device=Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'}), properties={'scope': 'host'})
2020-09-26 13:35:34,040 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'scope': 'host', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
2020-09-26 13:35:34,041 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet6', address='::1/128', device=Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'}), properties={'scope': 'host'})
2020-09-26 13:35:34,041 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'scope': 'host', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
2020-09-26 13:35:34,041 32048 DEBUG    [neutron_tempest_plugin.common.ip] Device parsed: Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'})
2020-09-26 13:35:34,041 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: Address(family='link/ether', address='fa:16:3e:d8:d8:fb', device=Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'}), properties={'brd': 'ff:ff:ff:ff:ff:ff'})
2020-09-26 13:35:34,042 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet', address='10.1.0.14/28', device=Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'}), properties={'brd': '10.1.0.15', 'scope': 'global'})
2020-09-26 13:35:34,042 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'brd': '10.1.0.15', 'scope': 'global', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
2020-09-26 13:35:34,042 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet6', address='fe80::f816:3eff:fed8:d8fb/64', device=Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'}), properties={'scope': 'link'})
2020-09-26 13:35:34,042 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'scope': 'link', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
2020-09-26 13:35:34,043 32048 DEBUG    [neutron_tempest_plugin.common.ip] Configuring VLAN subport interface 'ens3.10' on top of interface 'ens3' with IPs: 10.1.0.21/28
2020-09-26 13:35:34,044 32048 DEBUG    [neutron_tempest_plugin.common.shell] Executing command "sudo '/sbin/ip' link add link ens3 name ens3.10 type vlan id 10" on remote host '172.24.5.202' (timeout=None)...
2020-09-26 13:35:34,044 32048 INFO     [tempest.lib.common.ssh] Creating ssh connection to '172.24.5.202:22' as 'ubuntu' with public key authentication
2020-09-26 13:35:36,492 32048 INFO     [paramiko.transport] Connected (version 2.0, client OpenSSH_7.2p2)
2020-09-26 13:35:37,573 32048 INFO     [paramiko.transport] Authentication (publickey) successful!
2020-09-26 13:35:37,574 32048 INFO     [tempest.lib.common.ssh] ssh connection to ubuntu@172.24.5.202 successfully created
2020-09-26 13:36:12,729 32048 DEBUG    [neutron_tempest_plugin.common.shell] Command "sudo '/sbin/ip' link add link ens3 name ens3.10 type vlan id 10" succeeded:
stderr:
None
stdout:


2020-09-26 13:36:12,730 32048 DEBUG    [neutron_tempest_plugin.common.shell] Executing command "sudo '/sbin/ip' link set dev ens3.10 up" on remote host '172.24.5.202' (timeout=None)...
2020-09-26 13:36:12,730 32048 INFO     [tempest.lib.common.ssh] Creating ssh connection to '172.24.5.202:22' as 'ubuntu' with public key authentication
2020-09-26 13:36:16,082 32048 INFO     [paramiko.transport] Connected (version 2.0, client OpenSSH_7.2p2)
2020-09-26 13:36:17,033 32048 INFO     [paramiko.transport] Authentication (publickey) successful!
2020-09-26 13:36:17,034 32048 INFO     [tempest.lib.common.ssh] ssh connection to ubuntu@172.24.5.202 successfully created
2020-09-26 13:36:38,522 32048 DEBUG    [neutron_tempest_plugin.common.shell] Command "sudo '/sbin/ip' link set dev ens3.10 up" succeeded:
stderr:
None
stdout:


2020-09-26 13:36:38,523 32048 DEBUG    [neutron_tempest_plugin.common.shell] Executing command "sudo '/sbin/ip' address add 10.1.0.21/28 dev ens3.10" on remote host '172.24.5.202' (timeout=None)...
2020-09-26 13:36:38,523 32048 INFO     [tempest.lib.common.ssh] Creating ssh connection to '172.24.5.202:22' as 'ubuntu' with public key authentication
2020-09-26 13:36:40,572 32048 INFO     [paramiko.transport] Connected (version 2.0, client OpenSSH_7.2p2)
2020-09-26 13:36:42,308 32048 INFO     [paramiko.transport] Authentication (publickey) successful!
2020-09-26 13:36:42,309 32048 INFO     [tempest.lib.common.ssh] ssh connection to ubuntu@172.24.5.202 successfully created
2020-09-26 13:37:16,753 32048 DEBUG    [neutron_tempest_plugin.common.shell] Command "sudo '/sbin/ip' address add 10.1.0.21/28 dev ens3.10" succeeded:
stderr:
None
stdout:


2020-09-26 13:37:16,765 32048 DEBUG    [neutron_tempest_plugin.common.shell] Executing command "sudo '/sbin/ip' address list" on remote host '172.24.5.202' (timeout=None)...
2020-09-26 13:37:16,766 32048 INFO     [tempest.lib.common.ssh] Creating ssh connection to '172.24.5.202:22' as 'ubuntu' with public key authentication
2020-09-26 13:37:19,852 32048 INFO     [paramiko.transport] Connected (version 2.0, client OpenSSH_7.2p2)
2020-09-26 13:37:21,682 32048 INFO     [paramiko.transport] Authentication (publickey) successful!
2020-09-26 13:37:21,692 32048 INFO     [tempest.lib.common.ssh] ssh connection to ubuntu@172.24.5.202 successfully created
2020-09-26 14:09:31,790 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 204 DELETE http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb 0.586s
2020-09-26 14:09:31,791 32048 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, 26 Sep 2020 14:09:31 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-bee38d56-4009-40ad-959f-1c599108e673', 'x-compute-request-id': 'req-bee38d56-4009-40ad-959f-1c599108e673', 'connection': 'close', 'status': '204', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb'}
        Body: b''
2020-09-26 14:09:32,238 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 200 GET http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb 0.446s
2020-09-26 14:09:32,238 32048 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, 26 Sep 2020 14:09:31 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-length': '1625', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-797b21f4-7750-406f-a322-445f42c61051', 'x-compute-request-id': 'req-797b21f4-7750-406f-a322-445f42c61051', 'connection': 'close', 'status': '200', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb'}
        Body: b'{"server": {"id": "51b9c80c-d0d3-425c-b637-449e386506cb", "name": "tempest-server-test-994562558", "status": "ACTIVE", "tenant_id": "cce2d5eea8474da48f316de0bb6bc45b", "user_id": "4809961728504655a44a688269d2fdcf", "metadata": {}, "hostId": "65c4a23c230c49514063374756fcbbb44c38d04b6f7efdfd07766148", "image": {"id": "8d4d691b-d581-4cec-9a94-4fa3198bcf50", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/images/8d4d691b-d581-4cec-9a94-4fa3198bcf50"}]}, "flavor": {"id": "d1", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/flavors/d1"}]}, "created": "2020-09-26T13:29:57Z", "updated": "2020-09-26T14:09:32Z", "addresses": {"tempest-TrunkTest-1356610381": [{"version": 4, "addr": "10.1.0.12", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:c7:03:47"}, {"version": 4, "addr": "172.24.5.245", "OS-EXT-IPS:type": "floating", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:c7:03:47"}]}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb"}, {"rel": "bookmark", "href": "http://10.209.1.5/compute/servers/51b9c80c-d0d3-425c-b637-449e386506cb"}], "OS-DCF:diskConfig": "MANUAL", "progress": 0, "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "key_name": "tempest-TrunkTest-1356610381", "OS-SRV-USG:launched_at": "2020-09-26T13:30:07.000000", "OS-SRV-USG:terminated_at": null, "security_groups": [{"name": "tempest-TrunkTest-1356610381"}], "OS-EXT-STS:task_state": "deleting", "OS-EXT-STS:vm_state": "active", "OS-EXT-STS:power_state": 1, "os-extended-volumes:volumes_attached": []}}'
2020-09-26 14:09:33,729 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 200 GET http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb 0.481s
2020-09-26 14:09:33,729 32048 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, 26 Sep 2020 14:09:33 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-length': '1625', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-57ca4744-76d4-492a-b256-75f36e8963ba', 'x-compute-request-id': 'req-57ca4744-76d4-492a-b256-75f36e8963ba', 'connection': 'close', 'status': '200', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb'}
        Body: b'{"server": {"id": "51b9c80c-d0d3-425c-b637-449e386506cb", "name": "tempest-server-test-994562558", "status": "ACTIVE", "tenant_id": "cce2d5eea8474da48f316de0bb6bc45b", "user_id": "4809961728504655a44a688269d2fdcf", "metadata": {}, "hostId": "65c4a23c230c49514063374756fcbbb44c38d04b6f7efdfd07766148", "image": {"id": "8d4d691b-d581-4cec-9a94-4fa3198bcf50", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/images/8d4d691b-d581-4cec-9a94-4fa3198bcf50"}]}, "flavor": {"id": "d1", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/flavors/d1"}]}, "created": "2020-09-26T13:29:57Z", "updated": "2020-09-26T14:09:32Z", "addresses": {"tempest-TrunkTest-1356610381": [{"version": 4, "addr": "10.1.0.12", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:c7:03:47"}, {"version": 4, "addr": "172.24.5.245", "OS-EXT-IPS:type": "floating", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:c7:03:47"}]}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb"}, {"rel": "bookmark", "href": "http://10.209.1.5/compute/servers/51b9c80c-d0d3-425c-b637-449e386506cb"}], "OS-DCF:diskConfig": "MANUAL", "progress": 0, "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "key_name": "tempest-TrunkTest-1356610381", "OS-SRV-USG:launched_at": "2020-09-26T13:30:07.000000", "OS-SRV-USG:terminated_at": null, "security_groups": [{"name": "tempest-TrunkTest-1356610381"}], "OS-EXT-STS:task_state": "deleting", "OS-EXT-STS:vm_state": "active", "OS-EXT-STS:power_state": 1, "os-extended-volumes:volumes_attached": []}}'
2020-09-26 14:09:35,004 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 200 GET http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb 0.265s
2020-09-26 14:09:35,005 32048 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, 26 Sep 2020 14:09:34 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-length': '1303', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-8b9079e4-6a99-456b-9f51-78f09f76aaa5', 'x-compute-request-id': 'req-8b9079e4-6a99-456b-9f51-78f09f76aaa5', 'connection': 'close', 'status': '200', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb'}
        Body: b'{"server": {"id": "51b9c80c-d0d3-425c-b637-449e386506cb", "name": "tempest-server-test-994562558", "status": "DELETED", "tenant_id": "cce2d5eea8474da48f316de0bb6bc45b", "user_id": "4809961728504655a44a688269d2fdcf", "metadata": {}, "hostId": "65c4a23c230c49514063374756fcbbb44c38d04b6f7efdfd07766148", "image": {"id": "8d4d691b-d581-4cec-9a94-4fa3198bcf50", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/images/8d4d691b-d581-4cec-9a94-4fa3198bcf50"}]}, "flavor": {"id": "d1", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/flavors/d1"}]}, "created": "2020-09-26T13:29:57Z", "updated": "2020-09-26T14:09:35Z", "addresses": {}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb"}, {"rel": "bookmark", "href": "http://10.209.1.5/compute/servers/51b9c80c-d0d3-425c-b637-449e386506cb"}], "OS-DCF:diskConfig": "MANUAL", "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "key_name": "tempest-TrunkTest-1356610381", "OS-SRV-USG:launched_at": "2020-09-26T13:30:07.000000", "OS-SRV-USG:terminated_at": "2020-09-26T14:09:34.000000", "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "deleted", "OS-EXT-STS:power_state": 0, "os-extended-volumes:volumes_attached": []}}'
2020-09-26 14:09:35,012 32048 INFO     [tempest.common.waiters] State transition "ACTIVE/deleting" ==> "DELETED/None" after 3 second wait
2020-09-26 14:09:36,095 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 404 GET http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb 0.082s
2020-09-26 14:09:36,096 32048 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, 26 Sep 2020 14:09:36 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'content-type': 'application/json; charset=UTF-8', 'content-length': '111', 'x-openstack-request-id': 'req-7fe36cb3-5951-4803-86db-d39eb6a57903', 'x-compute-request-id': 'req-7fe36cb3-5951-4803-86db-d39eb6a57903', 'connection': 'close', 'status': '404', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb'}
        Body: b'{"itemNotFound": {"code": 404, "message": "Instance 51b9c80c-d0d3-425c-b637-449e386506cb could not be found."}}'
2020-09-26 14:09:36,291 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 204 DELETE http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd 0.195s
2020-09-26 14:09:36,292 32048 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, 26 Sep 2020 14:09:36 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-58bed038-6fa4-47c1-9bf4-9507e24bf315', 'x-compute-request-id': 'req-58bed038-6fa4-47c1-9bf4-9507e24bf315', 'connection': 'close', 'status': '204', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd'}
        Body: b''
2020-09-26 14:09:36,681 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 200 GET http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd 0.388s
2020-09-26 14:09:36,682 32048 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, 26 Sep 2020 14:09:36 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-length': '1613', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-509c2cb8-4ea2-45f5-a412-a35b769abbf3', 'x-compute-request-id': 'req-509c2cb8-4ea2-45f5-a412-a35b769abbf3', 'connection': 'close', 'status': '200', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd'}
        Body: b'{"server": {"id": "41058b63-fc17-4afd-b8db-9d257ff8fdcd", "name": "tempest-server-test-1541520469", "status": "SHUTOFF", "tenant_id": "cce2d5eea8474da48f316de0bb6bc45b", "user_id": "4809961728504655a44a688269d2fdcf", "metadata": {}, "hostId": "65c4a23c230c49514063374756fcbbb44c38d04b6f7efdfd07766148", "image": {"id": "8d4d691b-d581-4cec-9a94-4fa3198bcf50", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/images/8d4d691b-d581-4cec-9a94-4fa3198bcf50"}]}, "flavor": {"id": "d1", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/flavors/d1"}]}, "created": "2020-09-26T13:29:42Z", "updated": "2020-09-26T14:09:36Z", "addresses": {"tempest-TrunkTest-1356610381": [{"version": 4, "addr": "10.1.0.14", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:d8:d8:fb"}, {"version": 4, "addr": "172.24.5.202", "OS-EXT-IPS:type": "floating", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:d8:d8:fb"}]}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd"}, {"rel": "bookmark", "href": "http://10.209.1.5/compute/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd"}], "OS-DCF:diskConfig": "MANUAL", "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "key_name": "tempest-TrunkTest-1356610381", "OS-SRV-USG:launched_at": "2020-09-26T13:29:53.000000", "OS-SRV-USG:terminated_at": null, "security_groups": [{"name": "tempest-TrunkTest-1356610381"}], "OS-EXT-STS:task_state": "deleting", "OS-EXT-STS:vm_state": "stopped", "OS-EXT-STS:power_state": 4, "os-extended-volumes:volumes_attached": []}}'
2020-09-26 14:09:38,008 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 200 GET http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd 0.318s
2020-09-26 14:09:38,009 32048 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, 26 Sep 2020 14:09:37 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-length': '1613', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-89dfc1b8-e460-4952-91e1-6fcd0a8cf300', 'x-compute-request-id': 'req-89dfc1b8-e460-4952-91e1-6fcd0a8cf300', 'connection': 'close', 'status': '200', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd'}
        Body: b'{"server": {"id": "41058b63-fc17-4afd-b8db-9d257ff8fdcd", "name": "tempest-server-test-1541520469", "status": "SHUTOFF", "tenant_id": "cce2d5eea8474da48f316de0bb6bc45b", "user_id": "4809961728504655a44a688269d2fdcf", "metadata": {}, "hostId": "65c4a23c230c49514063374756fcbbb44c38d04b6f7efdfd07766148", "image": {"id": "8d4d691b-d581-4cec-9a94-4fa3198bcf50", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/images/8d4d691b-d581-4cec-9a94-4fa3198bcf50"}]}, "flavor": {"id": "d1", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/flavors/d1"}]}, "created": "2020-09-26T13:29:42Z", "updated": "2020-09-26T14:09:36Z", "addresses": {"tempest-TrunkTest-1356610381": [{"version": 4, "addr": "10.1.0.14", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:d8:d8:fb"}, {"version": 4, "addr": "172.24.5.202", "OS-EXT-IPS:type": "floating", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:d8:d8:fb"}]}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd"}, {"rel": "bookmark", "href": "http://10.209.1.5/compute/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd"}], "OS-DCF:diskConfig": "MANUAL", "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "key_name": "tempest-TrunkTest-1356610381", "OS-SRV-USG:launched_at": "2020-09-26T13:29:53.000000", "OS-SRV-USG:terminated_at": null, "security_groups": [{"name": "tempest-TrunkTest-1356610381"}], "OS-EXT-STS:task_state": "deleting", "OS-EXT-STS:vm_state": "stopped", "OS-EXT-STS:power_state": 4, "os-extended-volumes:volumes_attached": []}}'
2020-09-26 14:09:39,181 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 200 GET http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd 0.164s
2020-09-26 14:09:39,181 32048 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, 26 Sep 2020 14:09:39 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-length': '1304', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-f0343d9b-f5b3-4c9a-a647-5f853f88dcae', 'x-compute-request-id': 'req-f0343d9b-f5b3-4c9a-a647-5f853f88dcae', 'connection': 'close', 'status': '200', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd'}
        Body: b'{"server": {"id": "41058b63-fc17-4afd-b8db-9d257ff8fdcd", "name": "tempest-server-test-1541520469", "status": "DELETED", "tenant_id": "cce2d5eea8474da48f316de0bb6bc45b", "user_id": "4809961728504655a44a688269d2fdcf", "metadata": {}, "hostId": "65c4a23c230c49514063374756fcbbb44c38d04b6f7efdfd07766148", "image": {"id": "8d4d691b-d581-4cec-9a94-4fa3198bcf50", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/images/8d4d691b-d581-4cec-9a94-4fa3198bcf50"}]}, "flavor": {"id": "d1", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/flavors/d1"}]}, "created": "2020-09-26T13:29:42Z", "updated": "2020-09-26T14:09:39Z", "addresses": {}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd"}, {"rel": "bookmark", "href": "http://10.209.1.5/compute/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd"}], "OS-DCF:diskConfig": "MANUAL", "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "key_name": "tempest-TrunkTest-1356610381", "OS-SRV-USG:launched_at": "2020-09-26T13:29:53.000000", "OS-SRV-USG:terminated_at": "2020-09-26T14:09:38.000000", "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "deleted", "OS-EXT-STS:power_state": 0, "os-extended-volumes:volumes_attached": []}}'
2020-09-26 14:09:39,187 32048 INFO     [tempest.common.waiters] State transition "SHUTOFF/deleting" ==> "DELETED/None" after 3 second wait
2020-09-26 14:09:40,259 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 404 GET http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd 0.069s
2020-09-26 14:09:40,259 32048 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, 26 Sep 2020 14:09:40 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'content-type': 'application/json; charset=UTF-8', 'content-length': '111', 'x-openstack-request-id': 'req-7c16f9e4-f44e-4a40-a7ab-fd971a2b947a', 'x-compute-request-id': 'req-7c16f9e4-f44e-4a40-a7ab-fd971a2b947a', 'connection': 'close', 'status': '404', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd'}
        Body: b'{"itemNotFound": {"code": 404, "message": "Instance 41058b63-fc17-4afd-b8db-9d257ff8fdcd could not be found."}}'
}}}

Traceback (most recent call last):
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/neutron_tempest_plugin/scenario/test_trunk.py", line 272, in test_subport_connectivity
    vlan_subnet=vlan_subnet)
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/neutron_tempest_plugin/scenario/test_trunk.py", line 178, in _configure_vlan_subport
    for address in ip_command.list_addresses(port=vm.subport):
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/neutron_tempest_plugin/common/ip.py", line 92, in list_addresses
    output = self.execute('address', *command)
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/neutron_tempest_plugin/common/ip.py", line 52, in execute
    timeout=self.timeout).stdout
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/neutron_tempest_plugin/common/shell.py", line 69, in execute
    ssh_client=ssh_client)
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/neutron_tempest_plugin/common/shell.py", line 103, in execute_remote_command
    stdout = ssh_client.exec_command(command, timeout=timeout)
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/tenacity/__init__.py", line 329, in wrapped_f
    return self.call(f, *args, **kw)
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/tenacity/__init__.py", line 409, in call
    do = self.iter(retry_state=retry_state)
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/tenacity/__init__.py", line 356, in iter
    return fut.result()
  File "/usr/lib/python3.6/concurrent/futures/_base.py", line 425, in result
    return self.__get_result()
  File "/usr/lib/python3.6/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/tenacity/__init__.py", line 412, in call
    result = fn(*args, **kwargs)
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/neutron_tempest_plugin/common/ssh.py", line 178, in exec_command
    return super(Client, self).exec_command(cmd=cmd, encoding=encoding)
  File "/opt/stack/tempest/tempest/lib/common/ssh.py", line 160, in exec_command
    with transport.open_session() as channel:
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/paramiko/transport.py", line 879, in open_session
    timeout=timeout,
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/paramiko/transport.py", line 1001, in open_channel
    event.wait(0.1)
  File "/usr/lib/python3.6/threading.py", line 551, in wait
    signaled = self._cond.wait(timeout)
  File "/usr/lib/python3.6/threading.py", line 299, in wait
    gotit = waiter.acquire(True, timeout)
  File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/fixtures/_fixtures/timeout.py", line 52, in signal_handler
    raise TimeoutException()
fixtures._fixtures.timeout.TimeoutException

Additionally we don't log console log in case of failure in that place.
This should be improved too.

** Affects: neutron
     Importance: High
         Status: Confirmed


** Tags: gate-failure ovs trunk

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1897796

Title:
  Scenario test test_subport_connectivity failing from time to time

Status in neutron:
  Confirmed

Bug description:
  Test
  neutron_tempest_plugin.scenario.test_trunk.TrunkTest.test_subport_connectivity
  is failing from time to time.

  Example of failure:
  https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_d30/748367/16/check/neutron-tempest-plugin-scenario-openvswitch-ussuri/d30c240/testr_results.html

  Logstash query:
  http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22line%20272%2C%20in%20test_subport_connectivity%5C%22

  Stacktrace:
  2020-09-26 13:34:08,478 32048 INFO     [paramiko.transport] Connected (version 2.0, client OpenSSH_7.2p2)
  2020-09-26 13:34:10,019 32048 INFO     [paramiko.transport] Authentication (publickey) successful!
  2020-09-26 13:34:10,019 32048 INFO     [tempest.lib.common.ssh] ssh connection to ubuntu@172.24.5.202 successfully created
  2020-09-26 13:34:54,698 32048 DEBUG    [neutron_tempest_plugin.common.shell] Command "sudo '/sbin/ip' address list" succeeded:
  stderr:
  None
  stdout:
  1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1
      link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
      inet 127.0.0.1/8 scope host lo
         valid_lft forever preferred_lft forever
      inet6 ::1/128 scope host 
         valid_lft forever preferred_lft forever
  2: ens3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1400 qdisc pfifo_fast state UP group default qlen 1000
      link/ether fa:16:3e:d8:d8:fb brd ff:ff:ff:ff:ff:ff
      inet 10.1.0.14/28 brd 10.1.0.15 scope global ens3
         valid_lft forever preferred_lft forever
      inet6 fe80::f816:3eff:fed8:d8fb/64 scope link 
         valid_lft forever preferred_lft forever

  
  2020-09-26 13:34:54,699 32048 DEBUG    [neutron_tempest_plugin.common.ip] Device parsed: Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'})
  2020-09-26 13:34:54,700 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: Address(family='link/loopback', address='00:00:00:00:00:00', device=Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'}), properties={'brd': '00:00:00:00:00:00'})
  2020-09-26 13:34:54,700 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet', address='127.0.0.1/8', device=Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'}), properties={'scope': 'host'})
  2020-09-26 13:34:54,701 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'scope': 'host', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
  2020-09-26 13:34:54,701 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet6', address='::1/128', device=Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'}), properties={'scope': 'host'})
  2020-09-26 13:34:54,702 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'scope': 'host', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
  2020-09-26 13:34:54,702 32048 DEBUG    [neutron_tempest_plugin.common.ip] Device parsed: Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'})
  2020-09-26 13:34:54,702 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: Address(family='link/ether', address='fa:16:3e:d8:d8:fb', device=Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'}), properties={'brd': 'ff:ff:ff:ff:ff:ff'})
  2020-09-26 13:34:54,703 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet', address='10.1.0.14/28', device=Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'}), properties={'brd': '10.1.0.15', 'scope': 'global'})
  2020-09-26 13:34:54,703 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'brd': '10.1.0.15', 'scope': 'global', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
  2020-09-26 13:34:54,703 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet6', address='fe80::f816:3eff:fed8:d8fb/64', device=Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'}), properties={'scope': 'link'})
  2020-09-26 13:34:54,704 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'scope': 'link', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
  2020-09-26 13:34:54,706 32048 DEBUG    [neutron_tempest_plugin.common.shell] Executing command "sudo '/sbin/ip' address list" on remote host '172.24.5.202' (timeout=None)...
  2020-09-26 13:34:54,706 32048 INFO     [tempest.lib.common.ssh] Creating ssh connection to '172.24.5.202:22' as 'ubuntu' with public key authentication
  2020-09-26 13:34:57,146 32048 INFO     [paramiko.transport] Connected (version 2.0, client OpenSSH_7.2p2)
  2020-09-26 13:34:58,343 32048 INFO     [paramiko.transport] Authentication (publickey) successful!
  2020-09-26 13:34:58,343 32048 INFO     [tempest.lib.common.ssh] ssh connection to ubuntu@172.24.5.202 successfully created
  2020-09-26 13:35:34,039 32048 DEBUG    [neutron_tempest_plugin.common.shell] Command "sudo '/sbin/ip' address list" succeeded:
  stderr:
  None
  stdout:
  1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1
      link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
      inet 127.0.0.1/8 scope host lo
         valid_lft forever preferred_lft forever
      inet6 ::1/128 scope host 
         valid_lft forever preferred_lft forever
  2: ens3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1400 qdisc pfifo_fast state UP group default qlen 1000
      link/ether fa:16:3e:d8:d8:fb brd ff:ff:ff:ff:ff:ff
      inet 10.1.0.14/28 brd 10.1.0.15 scope global ens3
         valid_lft forever preferred_lft forever
      inet6 fe80::f816:3eff:fed8:d8fb/64 scope link 
         valid_lft forever preferred_lft forever

  
  2020-09-26 13:35:34,040 32048 DEBUG    [neutron_tempest_plugin.common.ip] Device parsed: Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'})
  2020-09-26 13:35:34,040 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: Address(family='link/loopback', address='00:00:00:00:00:00', device=Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'}), properties={'brd': '00:00:00:00:00:00'})
  2020-09-26 13:35:34,040 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet', address='127.0.0.1/8', device=Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'}), properties={'scope': 'host'})
  2020-09-26 13:35:34,040 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'scope': 'host', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
  2020-09-26 13:35:34,041 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet6', address='::1/128', device=Device(name='lo', parent=None, flags=['LOOPBACK', 'UP', 'LOWER_UP>'], properties={'mtu': '65536', 'qdisc': 'noqueue', 'state': 'UNKNOWN', 'group': 'default', 'qlen': '1'}), properties={'scope': 'host'})
  2020-09-26 13:35:34,041 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'scope': 'host', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
  2020-09-26 13:35:34,041 32048 DEBUG    [neutron_tempest_plugin.common.ip] Device parsed: Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'})
  2020-09-26 13:35:34,041 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: Address(family='link/ether', address='fa:16:3e:d8:d8:fb', device=Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'}), properties={'brd': 'ff:ff:ff:ff:ff:ff'})
  2020-09-26 13:35:34,042 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet', address='10.1.0.14/28', device=Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'}), properties={'brd': '10.1.0.15', 'scope': 'global'})
  2020-09-26 13:35:34,042 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'brd': '10.1.0.15', 'scope': 'global', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
  2020-09-26 13:35:34,042 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address parsed: InetAddress(family='inet6', address='fe80::f816:3eff:fed8:d8fb/64', device=Device(name='ens3', parent=None, flags=['BROADCAST', 'MULTICAST', 'UP', 'LOWER_UP>'], properties={'mtu': '1400', 'qdisc': 'pfifo_fast', 'state': 'UP', 'group': 'default', 'qlen': '1000'}), properties={'scope': 'link'})
  2020-09-26 13:35:34,042 32048 DEBUG    [neutron_tempest_plugin.common.ip] Address properties parsed: {'scope': 'link', 'valid_lft': 'forever', 'preferred_lft': 'forever'}
  2020-09-26 13:35:34,043 32048 DEBUG    [neutron_tempest_plugin.common.ip] Configuring VLAN subport interface 'ens3.10' on top of interface 'ens3' with IPs: 10.1.0.21/28
  2020-09-26 13:35:34,044 32048 DEBUG    [neutron_tempest_plugin.common.shell] Executing command "sudo '/sbin/ip' link add link ens3 name ens3.10 type vlan id 10" on remote host '172.24.5.202' (timeout=None)...
  2020-09-26 13:35:34,044 32048 INFO     [tempest.lib.common.ssh] Creating ssh connection to '172.24.5.202:22' as 'ubuntu' with public key authentication
  2020-09-26 13:35:36,492 32048 INFO     [paramiko.transport] Connected (version 2.0, client OpenSSH_7.2p2)
  2020-09-26 13:35:37,573 32048 INFO     [paramiko.transport] Authentication (publickey) successful!
  2020-09-26 13:35:37,574 32048 INFO     [tempest.lib.common.ssh] ssh connection to ubuntu@172.24.5.202 successfully created
  2020-09-26 13:36:12,729 32048 DEBUG    [neutron_tempest_plugin.common.shell] Command "sudo '/sbin/ip' link add link ens3 name ens3.10 type vlan id 10" succeeded:
  stderr:
  None
  stdout:

  
  2020-09-26 13:36:12,730 32048 DEBUG    [neutron_tempest_plugin.common.shell] Executing command "sudo '/sbin/ip' link set dev ens3.10 up" on remote host '172.24.5.202' (timeout=None)...
  2020-09-26 13:36:12,730 32048 INFO     [tempest.lib.common.ssh] Creating ssh connection to '172.24.5.202:22' as 'ubuntu' with public key authentication
  2020-09-26 13:36:16,082 32048 INFO     [paramiko.transport] Connected (version 2.0, client OpenSSH_7.2p2)
  2020-09-26 13:36:17,033 32048 INFO     [paramiko.transport] Authentication (publickey) successful!
  2020-09-26 13:36:17,034 32048 INFO     [tempest.lib.common.ssh] ssh connection to ubuntu@172.24.5.202 successfully created
  2020-09-26 13:36:38,522 32048 DEBUG    [neutron_tempest_plugin.common.shell] Command "sudo '/sbin/ip' link set dev ens3.10 up" succeeded:
  stderr:
  None
  stdout:

  
  2020-09-26 13:36:38,523 32048 DEBUG    [neutron_tempest_plugin.common.shell] Executing command "sudo '/sbin/ip' address add 10.1.0.21/28 dev ens3.10" on remote host '172.24.5.202' (timeout=None)...
  2020-09-26 13:36:38,523 32048 INFO     [tempest.lib.common.ssh] Creating ssh connection to '172.24.5.202:22' as 'ubuntu' with public key authentication
  2020-09-26 13:36:40,572 32048 INFO     [paramiko.transport] Connected (version 2.0, client OpenSSH_7.2p2)
  2020-09-26 13:36:42,308 32048 INFO     [paramiko.transport] Authentication (publickey) successful!
  2020-09-26 13:36:42,309 32048 INFO     [tempest.lib.common.ssh] ssh connection to ubuntu@172.24.5.202 successfully created
  2020-09-26 13:37:16,753 32048 DEBUG    [neutron_tempest_plugin.common.shell] Command "sudo '/sbin/ip' address add 10.1.0.21/28 dev ens3.10" succeeded:
  stderr:
  None
  stdout:

  
  2020-09-26 13:37:16,765 32048 DEBUG    [neutron_tempest_plugin.common.shell] Executing command "sudo '/sbin/ip' address list" on remote host '172.24.5.202' (timeout=None)...
  2020-09-26 13:37:16,766 32048 INFO     [tempest.lib.common.ssh] Creating ssh connection to '172.24.5.202:22' as 'ubuntu' with public key authentication
  2020-09-26 13:37:19,852 32048 INFO     [paramiko.transport] Connected (version 2.0, client OpenSSH_7.2p2)
  2020-09-26 13:37:21,682 32048 INFO     [paramiko.transport] Authentication (publickey) successful!
  2020-09-26 13:37:21,692 32048 INFO     [tempest.lib.common.ssh] ssh connection to ubuntu@172.24.5.202 successfully created
  2020-09-26 14:09:31,790 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 204 DELETE http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb 0.586s
  2020-09-26 14:09:31,791 32048 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, 26 Sep 2020 14:09:31 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-bee38d56-4009-40ad-959f-1c599108e673', 'x-compute-request-id': 'req-bee38d56-4009-40ad-959f-1c599108e673', 'connection': 'close', 'status': '204', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb'}
          Body: b''
  2020-09-26 14:09:32,238 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 200 GET http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb 0.446s
  2020-09-26 14:09:32,238 32048 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, 26 Sep 2020 14:09:31 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-length': '1625', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-797b21f4-7750-406f-a322-445f42c61051', 'x-compute-request-id': 'req-797b21f4-7750-406f-a322-445f42c61051', 'connection': 'close', 'status': '200', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb'}
          Body: b'{"server": {"id": "51b9c80c-d0d3-425c-b637-449e386506cb", "name": "tempest-server-test-994562558", "status": "ACTIVE", "tenant_id": "cce2d5eea8474da48f316de0bb6bc45b", "user_id": "4809961728504655a44a688269d2fdcf", "metadata": {}, "hostId": "65c4a23c230c49514063374756fcbbb44c38d04b6f7efdfd07766148", "image": {"id": "8d4d691b-d581-4cec-9a94-4fa3198bcf50", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/images/8d4d691b-d581-4cec-9a94-4fa3198bcf50"}]}, "flavor": {"id": "d1", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/flavors/d1"}]}, "created": "2020-09-26T13:29:57Z", "updated": "2020-09-26T14:09:32Z", "addresses": {"tempest-TrunkTest-1356610381": [{"version": 4, "addr": "10.1.0.12", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:c7:03:47"}, {"version": 4, "addr": "172.24.5.245", "OS-EXT-IPS:type": "floating", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:c7:03:47"}]}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb"}, {"rel": "bookmark", "href": "http://10.209.1.5/compute/servers/51b9c80c-d0d3-425c-b637-449e386506cb"}], "OS-DCF:diskConfig": "MANUAL", "progress": 0, "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "key_name": "tempest-TrunkTest-1356610381", "OS-SRV-USG:launched_at": "2020-09-26T13:30:07.000000", "OS-SRV-USG:terminated_at": null, "security_groups": [{"name": "tempest-TrunkTest-1356610381"}], "OS-EXT-STS:task_state": "deleting", "OS-EXT-STS:vm_state": "active", "OS-EXT-STS:power_state": 1, "os-extended-volumes:volumes_attached": []}}'
  2020-09-26 14:09:33,729 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 200 GET http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb 0.481s
  2020-09-26 14:09:33,729 32048 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, 26 Sep 2020 14:09:33 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-length': '1625', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-57ca4744-76d4-492a-b256-75f36e8963ba', 'x-compute-request-id': 'req-57ca4744-76d4-492a-b256-75f36e8963ba', 'connection': 'close', 'status': '200', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb'}
          Body: b'{"server": {"id": "51b9c80c-d0d3-425c-b637-449e386506cb", "name": "tempest-server-test-994562558", "status": "ACTIVE", "tenant_id": "cce2d5eea8474da48f316de0bb6bc45b", "user_id": "4809961728504655a44a688269d2fdcf", "metadata": {}, "hostId": "65c4a23c230c49514063374756fcbbb44c38d04b6f7efdfd07766148", "image": {"id": "8d4d691b-d581-4cec-9a94-4fa3198bcf50", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/images/8d4d691b-d581-4cec-9a94-4fa3198bcf50"}]}, "flavor": {"id": "d1", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/flavors/d1"}]}, "created": "2020-09-26T13:29:57Z", "updated": "2020-09-26T14:09:32Z", "addresses": {"tempest-TrunkTest-1356610381": [{"version": 4, "addr": "10.1.0.12", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:c7:03:47"}, {"version": 4, "addr": "172.24.5.245", "OS-EXT-IPS:type": "floating", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:c7:03:47"}]}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb"}, {"rel": "bookmark", "href": "http://10.209.1.5/compute/servers/51b9c80c-d0d3-425c-b637-449e386506cb"}], "OS-DCF:diskConfig": "MANUAL", "progress": 0, "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "key_name": "tempest-TrunkTest-1356610381", "OS-SRV-USG:launched_at": "2020-09-26T13:30:07.000000", "OS-SRV-USG:terminated_at": null, "security_groups": [{"name": "tempest-TrunkTest-1356610381"}], "OS-EXT-STS:task_state": "deleting", "OS-EXT-STS:vm_state": "active", "OS-EXT-STS:power_state": 1, "os-extended-volumes:volumes_attached": []}}'
  2020-09-26 14:09:35,004 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 200 GET http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb 0.265s
  2020-09-26 14:09:35,005 32048 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, 26 Sep 2020 14:09:34 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-length': '1303', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-8b9079e4-6a99-456b-9f51-78f09f76aaa5', 'x-compute-request-id': 'req-8b9079e4-6a99-456b-9f51-78f09f76aaa5', 'connection': 'close', 'status': '200', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb'}
          Body: b'{"server": {"id": "51b9c80c-d0d3-425c-b637-449e386506cb", "name": "tempest-server-test-994562558", "status": "DELETED", "tenant_id": "cce2d5eea8474da48f316de0bb6bc45b", "user_id": "4809961728504655a44a688269d2fdcf", "metadata": {}, "hostId": "65c4a23c230c49514063374756fcbbb44c38d04b6f7efdfd07766148", "image": {"id": "8d4d691b-d581-4cec-9a94-4fa3198bcf50", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/images/8d4d691b-d581-4cec-9a94-4fa3198bcf50"}]}, "flavor": {"id": "d1", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/flavors/d1"}]}, "created": "2020-09-26T13:29:57Z", "updated": "2020-09-26T14:09:35Z", "addresses": {}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb"}, {"rel": "bookmark", "href": "http://10.209.1.5/compute/servers/51b9c80c-d0d3-425c-b637-449e386506cb"}], "OS-DCF:diskConfig": "MANUAL", "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "key_name": "tempest-TrunkTest-1356610381", "OS-SRV-USG:launched_at": "2020-09-26T13:30:07.000000", "OS-SRV-USG:terminated_at": "2020-09-26T14:09:34.000000", "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "deleted", "OS-EXT-STS:power_state": 0, "os-extended-volumes:volumes_attached": []}}'
  2020-09-26 14:09:35,012 32048 INFO     [tempest.common.waiters] State transition "ACTIVE/deleting" ==> "DELETED/None" after 3 second wait
  2020-09-26 14:09:36,095 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 404 GET http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb 0.082s
  2020-09-26 14:09:36,096 32048 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, 26 Sep 2020 14:09:36 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'content-type': 'application/json; charset=UTF-8', 'content-length': '111', 'x-openstack-request-id': 'req-7fe36cb3-5951-4803-86db-d39eb6a57903', 'x-compute-request-id': 'req-7fe36cb3-5951-4803-86db-d39eb6a57903', 'connection': 'close', 'status': '404', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/51b9c80c-d0d3-425c-b637-449e386506cb'}
          Body: b'{"itemNotFound": {"code": 404, "message": "Instance 51b9c80c-d0d3-425c-b637-449e386506cb could not be found."}}'
  2020-09-26 14:09:36,291 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 204 DELETE http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd 0.195s
  2020-09-26 14:09:36,292 32048 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, 26 Sep 2020 14:09:36 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-58bed038-6fa4-47c1-9bf4-9507e24bf315', 'x-compute-request-id': 'req-58bed038-6fa4-47c1-9bf4-9507e24bf315', 'connection': 'close', 'status': '204', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd'}
          Body: b''
  2020-09-26 14:09:36,681 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 200 GET http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd 0.388s
  2020-09-26 14:09:36,682 32048 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, 26 Sep 2020 14:09:36 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-length': '1613', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-509c2cb8-4ea2-45f5-a412-a35b769abbf3', 'x-compute-request-id': 'req-509c2cb8-4ea2-45f5-a412-a35b769abbf3', 'connection': 'close', 'status': '200', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd'}
          Body: b'{"server": {"id": "41058b63-fc17-4afd-b8db-9d257ff8fdcd", "name": "tempest-server-test-1541520469", "status": "SHUTOFF", "tenant_id": "cce2d5eea8474da48f316de0bb6bc45b", "user_id": "4809961728504655a44a688269d2fdcf", "metadata": {}, "hostId": "65c4a23c230c49514063374756fcbbb44c38d04b6f7efdfd07766148", "image": {"id": "8d4d691b-d581-4cec-9a94-4fa3198bcf50", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/images/8d4d691b-d581-4cec-9a94-4fa3198bcf50"}]}, "flavor": {"id": "d1", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/flavors/d1"}]}, "created": "2020-09-26T13:29:42Z", "updated": "2020-09-26T14:09:36Z", "addresses": {"tempest-TrunkTest-1356610381": [{"version": 4, "addr": "10.1.0.14", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:d8:d8:fb"}, {"version": 4, "addr": "172.24.5.202", "OS-EXT-IPS:type": "floating", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:d8:d8:fb"}]}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd"}, {"rel": "bookmark", "href": "http://10.209.1.5/compute/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd"}], "OS-DCF:diskConfig": "MANUAL", "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "key_name": "tempest-TrunkTest-1356610381", "OS-SRV-USG:launched_at": "2020-09-26T13:29:53.000000", "OS-SRV-USG:terminated_at": null, "security_groups": [{"name": "tempest-TrunkTest-1356610381"}], "OS-EXT-STS:task_state": "deleting", "OS-EXT-STS:vm_state": "stopped", "OS-EXT-STS:power_state": 4, "os-extended-volumes:volumes_attached": []}}'
  2020-09-26 14:09:38,008 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 200 GET http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd 0.318s
  2020-09-26 14:09:38,009 32048 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, 26 Sep 2020 14:09:37 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-length': '1613', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-89dfc1b8-e460-4952-91e1-6fcd0a8cf300', 'x-compute-request-id': 'req-89dfc1b8-e460-4952-91e1-6fcd0a8cf300', 'connection': 'close', 'status': '200', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd'}
          Body: b'{"server": {"id": "41058b63-fc17-4afd-b8db-9d257ff8fdcd", "name": "tempest-server-test-1541520469", "status": "SHUTOFF", "tenant_id": "cce2d5eea8474da48f316de0bb6bc45b", "user_id": "4809961728504655a44a688269d2fdcf", "metadata": {}, "hostId": "65c4a23c230c49514063374756fcbbb44c38d04b6f7efdfd07766148", "image": {"id": "8d4d691b-d581-4cec-9a94-4fa3198bcf50", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/images/8d4d691b-d581-4cec-9a94-4fa3198bcf50"}]}, "flavor": {"id": "d1", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/flavors/d1"}]}, "created": "2020-09-26T13:29:42Z", "updated": "2020-09-26T14:09:36Z", "addresses": {"tempest-TrunkTest-1356610381": [{"version": 4, "addr": "10.1.0.14", "OS-EXT-IPS:type": "fixed", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:d8:d8:fb"}, {"version": 4, "addr": "172.24.5.202", "OS-EXT-IPS:type": "floating", "OS-EXT-IPS-MAC:mac_addr": "fa:16:3e:d8:d8:fb"}]}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd"}, {"rel": "bookmark", "href": "http://10.209.1.5/compute/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd"}], "OS-DCF:diskConfig": "MANUAL", "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "key_name": "tempest-TrunkTest-1356610381", "OS-SRV-USG:launched_at": "2020-09-26T13:29:53.000000", "OS-SRV-USG:terminated_at": null, "security_groups": [{"name": "tempest-TrunkTest-1356610381"}], "OS-EXT-STS:task_state": "deleting", "OS-EXT-STS:vm_state": "stopped", "OS-EXT-STS:power_state": 4, "os-extended-volumes:volumes_attached": []}}'
  2020-09-26 14:09:39,181 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 200 GET http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd 0.164s
  2020-09-26 14:09:39,181 32048 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, 26 Sep 2020 14:09:39 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'content-length': '1304', 'content-type': 'application/json', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'x-openstack-request-id': 'req-f0343d9b-f5b3-4c9a-a647-5f853f88dcae', 'x-compute-request-id': 'req-f0343d9b-f5b3-4c9a-a647-5f853f88dcae', 'connection': 'close', 'status': '200', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd'}
          Body: b'{"server": {"id": "41058b63-fc17-4afd-b8db-9d257ff8fdcd", "name": "tempest-server-test-1541520469", "status": "DELETED", "tenant_id": "cce2d5eea8474da48f316de0bb6bc45b", "user_id": "4809961728504655a44a688269d2fdcf", "metadata": {}, "hostId": "65c4a23c230c49514063374756fcbbb44c38d04b6f7efdfd07766148", "image": {"id": "8d4d691b-d581-4cec-9a94-4fa3198bcf50", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/images/8d4d691b-d581-4cec-9a94-4fa3198bcf50"}]}, "flavor": {"id": "d1", "links": [{"rel": "bookmark", "href": "http://10.209.1.5/compute/flavors/d1"}]}, "created": "2020-09-26T13:29:42Z", "updated": "2020-09-26T14:09:39Z", "addresses": {}, "accessIPv4": "", "accessIPv6": "", "links": [{"rel": "self", "href": "http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd"}, {"rel": "bookmark", "href": "http://10.209.1.5/compute/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd"}], "OS-DCF:diskConfig": "MANUAL", "OS-EXT-AZ:availability_zone": "nova", "config_drive": "", "key_name": "tempest-TrunkTest-1356610381", "OS-SRV-USG:launched_at": "2020-09-26T13:29:53.000000", "OS-SRV-USG:terminated_at": "2020-09-26T14:09:38.000000", "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "deleted", "OS-EXT-STS:power_state": 0, "os-extended-volumes:volumes_attached": []}}'
  2020-09-26 14:09:39,187 32048 INFO     [tempest.common.waiters] State transition "SHUTOFF/deleting" ==> "DELETED/None" after 3 second wait
  2020-09-26 14:09:40,259 32048 INFO     [tempest.lib.common.rest_client] Request (TrunkTest:_run_cleanups): 404 GET http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd 0.069s
  2020-09-26 14:09:40,259 32048 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, 26 Sep 2020 14:09:40 GMT', 'server': 'Apache/2.4.29 (Ubuntu)', 'openstack-api-version': 'compute 2.1', 'x-openstack-nova-api-version': '2.1', 'vary': 'OpenStack-API-Version,X-OpenStack-Nova-API-Version', 'content-type': 'application/json; charset=UTF-8', 'content-length': '111', 'x-openstack-request-id': 'req-7c16f9e4-f44e-4a40-a7ab-fd971a2b947a', 'x-compute-request-id': 'req-7c16f9e4-f44e-4a40-a7ab-fd971a2b947a', 'connection': 'close', 'status': '404', 'content-location': 'http://10.209.1.5/compute/v2.1/servers/41058b63-fc17-4afd-b8db-9d257ff8fdcd'}
          Body: b'{"itemNotFound": {"code": 404, "message": "Instance 41058b63-fc17-4afd-b8db-9d257ff8fdcd could not be found."}}'
  }}}

  Traceback (most recent call last):
    File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/neutron_tempest_plugin/scenario/test_trunk.py", line 272, in test_subport_connectivity
      vlan_subnet=vlan_subnet)
    File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/neutron_tempest_plugin/scenario/test_trunk.py", line 178, in _configure_vlan_subport
      for address in ip_command.list_addresses(port=vm.subport):
    File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/neutron_tempest_plugin/common/ip.py", line 92, in list_addresses
      output = self.execute('address', *command)
    File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/neutron_tempest_plugin/common/ip.py", line 52, in execute
      timeout=self.timeout).stdout
    File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/neutron_tempest_plugin/common/shell.py", line 69, in execute
      ssh_client=ssh_client)
    File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/neutron_tempest_plugin/common/shell.py", line 103, in execute_remote_command
      stdout = ssh_client.exec_command(command, timeout=timeout)
    File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/tenacity/__init__.py", line 329, in wrapped_f
      return self.call(f, *args, **kw)
    File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/tenacity/__init__.py", line 409, in call
      do = self.iter(retry_state=retry_state)
    File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/tenacity/__init__.py", line 356, in iter
      return fut.result()
    File "/usr/lib/python3.6/concurrent/futures/_base.py", line 425, in result
      return self.__get_result()
    File "/usr/lib/python3.6/concurrent/futures/_base.py", line 384, in __get_result
      raise self._exception
    File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/tenacity/__init__.py", line 412, in call
      result = fn(*args, **kwargs)
    File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/neutron_tempest_plugin/common/ssh.py", line 178, in exec_command
      return super(Client, self).exec_command(cmd=cmd, encoding=encoding)
    File "/opt/stack/tempest/tempest/lib/common/ssh.py", line 160, in exec_command
      with transport.open_session() as channel:
    File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/paramiko/transport.py", line 879, in open_session
      timeout=timeout,
    File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/paramiko/transport.py", line 1001, in open_channel
      event.wait(0.1)
    File "/usr/lib/python3.6/threading.py", line 551, in wait
      signaled = self._cond.wait(timeout)
    File "/usr/lib/python3.6/threading.py", line 299, in wait
      gotit = waiter.acquire(True, timeout)
    File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/fixtures/_fixtures/timeout.py", line 52, in signal_handler
      raise TimeoutException()
  fixtures._fixtures.timeout.TimeoutException

  Additionally we don't log console log in case of failure in that
  place. This should be improved too.

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