ovs_lilb failing to find interface

[Jamie Lennox]

This is failing patches in the check-tempest-dsvm-neutron-pg and check-tempest-dsvm-neutron-pg-2 gates. Failure example: http://logs.openstack.org/03/135903/1/check/check-tempest-dsvm-neutron-pg/eb2d9f2/

Traceback:
tempest.api.network.test_security_groups.SecGroupIPv6Test.test_create_security_group_rule_with_protocol_integer_value[gate,smoke]
2014-11-25 20:47:03.448 | ---------------------------------------------------------------------------------------------------------------------------------
2014-11-25 20:47:03.448 |
2014-11-25 20:47:03.449 | Captured traceback:
2014-11-25 20:47:03.449 | ~~~~~~~~~~~~~~~~~~~
2014-11-25 20:47:03.449 | Traceback (most recent call last):
2014-11-25 20:47:03.450 | File "tempest/api/network/test_security_groups.py", line 227, in test_create_security_group_rule_with_protocol_integer_value
2014-11-25 20:47:03.450 | protocol=protocol
2014-11-25 20:47:03.450 | File "tempest/services/network/network_client_base.py", line 151, in _create
2014-11-25 20:47:03.451 | resp, body = self.post(uri, post_data)
2014-11-25 20:47:03.451 | File "tempest/services/network/network_client_base.py", line 74, in post
2014-11-25 20:47:03.451 | return self.rest_client.post(uri, body, headers)
2014-11-25 20:47:03.452 | File "tempest/common/rest_client.py", line 234, in post
2014-11-25 20:47:03.452 | return self.request('POST', url, extra_headers, headers, body)
2014-11-25 20:47:03.452 | File "tempest/common/rest_client.py", line 454, in request
2014-11-25 20:47:03.453 | resp, resp_body)
2014-11-25 20:47:03.453 | File "tempest/common/rest_client.py", line 550, in _error_checker
2014-11-25 20:47:03.453 | raise exceptions.ServerFault(message)
2014-11-25 20:47:03.454 | ServerFault: Got server fault
2014-11-25 20:47:03.454 | Details: {"NeutronError": "Request Failed: internal server error while processing your request."}
2014-11-25 20:47:03.454 | Traceback (most recent call last):
2014-11-25 20:47:03.454 | _StringException: Empty attachments:
2014-11-25 20:47:03.455 | stderr
2014-11-25 20:47:03.455 | stdout
2014-11-25 20:47:03.455 |
2014-11-25 20:47:03.456 | pythonlogging:'': {{{
2014-11-25 20:47:03.456 | 2014-11-25 20:17:07,635 29712 DEBUG [tempest.common.rest_client] Request (SecGroupIPv6Test:test_create_security_group_rule_with_protocol_integer_value): 201 POST http://127.0.0.1:9696/v2.0/security-groups 0.029s
2014-11-25 20:47:03.457 | Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
2014-11-25 20:47:03.457 | Body: {"security_group": {"name": "secgroup--155432828"}}
2014-11-25 20:47:03.457 | Response - Headers: {'status': '201', 'content-length': '829', 'connection': 'close', 'date': 'Tue, 25 Nov 2014 20:17:07 GMT', 'content-type': 'application/json; charset=UTF-8', 'x-openstack-request-id': 'req-671af274-78f7-4302-be84-07887880f8f8'}
2014-11-25 20:47:03.458 | Body: {"security_group": {"tenant_id": "41829285256b4b84a4bcdbf2fccf4435", "description": "", "id": "0bf40539-4240-4d69-a72d-3ed477b765a8", "security_group_rules": [{"remote_group_id": null, "direction": "egress", "remote_ip_prefix": null, "protocol": null, "ethertype": "IPv4", "tenant_id": "41829285256b4b84a4bcdbf2fccf4435", "port_range_max": null, "port_range_min": null, "id": "3ca48175-2821-47f3-93c0-f5b17c752adf", "security_group_id": "0bf40539-4240-4d69-a72d-3ed477b765a8"}, {"remote_group_id": null, "direction": "egress", "remote_ip_prefix": null, "protocol": null, "ethertype": "IPv6", "tenant_id": "41829285256b4b84a4bcdbf2fccf4435", "port_range_max": null, "port_range_min": null, "id": "813284c1-a71e-4b18-ab2c-5c2e2b183c44", "security_group_id": "0bf40539-4240-4d69-a72d-3ed477b765a8"}], "name": "secgroup--155432828"}}
2014-11-25 20:47:03.458 | 2014-11-25 20:17:07,667 29712 DEBUG [tempest.common.rest_client] Request (SecGroupIPv6Test:test_create_security_group_rule_with_protocol_integer_value): 500 POST http://127.0.0.1:9696/v2.0/security-group-rules 0.031s
2014-11-25 20:47:03.458 | Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
2014-11-25 20:47:03.459 | Body: {"security_group_rule": {"direction": "ingress", "protocol": 17, "security_group_id": "0bf40539-4240-4d69-a72d-3ed477b765a8"}}
2014-11-25 20:47:03.459 | Response - Headers: {'status': '500', 'content-length': '88', 'connection': 'close', 'date': 'Tue, 25 Nov 2014 20:17:07 GMT', 'content-type': 'application/json; charset=UTF-8', 'x-openstack-request-id': 'req-0f9c179a-3b90-42f7-bbe4-b0bef4bf9390'}
2014-11-25 20:47:03.459 | Body: {"NeutronError": "Request Failed: internal server error while processing your request."}
2014-11-25 20:47:03.460 | 2014-11-25 20:17:07,693 29712 DEBUG [tempest.common.rest_client] Request (SecGroupIPv6Test:_run_cleanups): 204 DELETE http://127.0.0.1:9696/v2.0/security-groups/0bf40539-4240-4d69-a72d-3ed477b765a8 0.024s
2014-11-25 20:47:03.460 | Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
2014-11-25 20:47:03.461 | Body: None
2014-11-25 20:47:03.461 | Response - Headers: {'date': 'Tue, 25 Nov 2014 20:17:07 GMT', 'status': '204', 'connection': 'close', 'content-length': '0', 'x-openstack-request-id': 'req-bd53bf38-a76c-492d-8b13-87bacd0800bb'}
2014-11-25 20:47:03.461 | Body:
2014-11-25 20:47:03.462 | 2014-11-25 20:17:07,707 29712 DEBUG [tempest.common.rest_client] Request (SecGroupIPv6Test:_run_cleanups): 200 GET http://127.0.0.1:9696/v2.0/security-groups 0.013s
2014-11-25 20:47:03.462 | Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
2014-11-25 20:47:03.462 | Body: None
2014-11-25 20:47:03.463 | Response - Headers: {'status': '200', 'content-length': '1535', 'content-location': 'http://127.0.0.1:9696/v2.0/security-groups', 'connection': 'close', 'date': 'Tue, 25 Nov 2014 20:17:07 GMT', 'content-type': 'application/json; charset=UTF-8', 'x-openstack-request-id': 'req-4acd67af-a88d-4679-b94d-f7a2286a5dcb'}
2014-11-25 20:47:03.463 | Body: {"security_groups": [{"tenant_id": "41829285256b4b84a4bcdbf2fccf4435", "description": "default", "id": "b77f6461-43ba-4db1-94ba-1ae29e384fa9", "security_group_rules": [{"remote_group_id": "b77f6461-43ba-4db1-94ba-1ae29e384fa9", "direction": "ingress", "remote_ip_prefix": null, "protocol": null, "ethertype": "IPv4", "tenant_id": "41829285256b4b84a4bcdbf2fccf4435", "port_range_max": null, "port_range_min": null, "id": "394a873c-9e87-4bf7-8276-7b8c44dd5c04", "security_group_id": "b77f6461-43ba-4db1-94ba-1ae29e384fa9"}, {"remote_group_id": null, "direction": "egress", "remote_ip_prefix": null, "protocol": null, "ethertype": "IPv4", "tenant_id": "41829285256b4b84a4bcdbf2fccf4435", "port_range_max": null, "port_range_min": null, "id": "63991ca1-35db-406c-95de-67ed682d9339", "security_group_id": "b77f6461-43ba-4db1-94ba-1ae29e384fa9"}, {"remote_group_id": "b77f6461-43ba-4db1-94ba-1ae29e384fa9", "direction": "ingress", "remote_ip_prefix": null, "protocol": null, "ethertype": "IPv6", "tenant_id": "41829285256b4b84a4bcdbf2fccf4435", "port_range_max": null, "port_range_min": null, "id": "2805d411-3f38-40e1-9b50-943369345b83", "security_group_id": "b77f6461-43ba-4db1-94ba-1ae29e384fa9"}, {"remote_group_id": null, "direction": "egress", "remote_ip_prefix": null, "protocol": null, "ethertype": "IPv6", "tenant_id": "41829285256b4b84a4bcdbf2fccf4435", "port_range_max": null, "port_range_min": null, "id": "d61e6221-a9e1-402a-81c1-64a47b4bfdf3", "security_group_id": "b77f6461-43ba-4db1-94ba-1ae29e384fa9"}], "name": "default"}]}
2014-11-25 20:47:03.463 | }}}
2014-11-25 20:47:03.464 |
2014-11-25 20:47:03.464 | Traceback (most recent call last):
2014-11-25 20:47:03.464 | File "tempest/api/network/test_security_groups.py", line 227, in test_create_security_group_rule_with_protocol_integer_value
2014-11-25 20:47:03.464 | protocol=protocol
2014-11-25 20:47:03.465 | File "tempest/services/network/network_client_base.py", line 151, in _create
2014-11-25 20:47:03.465 | resp, body = self.post(uri, post_data)
2014-11-25 20:47:03.465 | File "tempest/services/network/network_client_base.py", line 74, in post
2014-11-25 20:47:03.466 | return self.rest_client.post(uri, body, headers)
2014-11-25 20:47:03.466 | File "tempest/common/rest_client.py", line 234, in post
2014-11-25 20:47:03.466 | return self.request('POST', url, extra_headers, headers, body)
2014-11-25 20:47:03.467 | File "tempest/common/rest_client.py", line 454, in request
2014-11-25 20:47:03.467 | resp, resp_body)
2014-11-25 20:47:03.467 | File "tempest/common/rest_client.py", line 550, in _error_checker
2014-11-25 20:47:03.467 | raise exceptions.ServerFault(message)
2014-11-25 20:47:03.468 | ServerFault: Got server fault
2014-11-25 20:47:03.468 | Details: {"NeutronError": "Request Failed: internal server error while processing your request."}
2014-11-25 20:47:03.468 |
2014-11-25 20:47:03.469 | Traceback (most recent call last):
2014-11-25 20:47:03.469 | _StringException: Empty attachments:
2014-11-25 20:47:03.469 | stderr
2014-11-25 20:47:03.470 | stdout
2014-11-25 20:47:03.470 |

The errors i see in neutron agent are:

2014-11-25 20:15:39.455 21778 ERROR neutron.agent.linux.ovs_lib [-] Interface tapa7ad1b7c-8f not found.
2014-11-25 20:15:39.455 21778 TRACE neutron.agent.linux.ovs_lib Traceback (most recent call last):
2014-11-25 20:15:39.455 21778 TRACE neutron.agent.linux.ovs_lib File "/opt/stack/new/neutron/neutron/agent/linux/ovs_lib.py", line 463, in get_bridge_for_iface
2014-11-25 20:15:39.455 21778 TRACE neutron.agent.linux.ovs_lib return utils.execute(args, root_helper=root_helper).strip()
2014-11-25 20:15:39.455 21778 TRACE neutron.agent.linux.ovs_lib File "/opt/stack/new/neutron/neutron/agent/linux/utils.py", line 76, in execute
2014-11-25 20:15:39.455 21778 TRACE neutron.agent.linux.ovs_lib raise RuntimeError(m)
2014-11-25 20:15:39.455 21778 TRACE neutron.agent.linux.ovs_lib RuntimeError:
2014-11-25 20:15:39.455 21778 TRACE neutron.agent.linux.ovs_lib Command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ovs-vsctl', '--timeout=10', 'iface-to-br', 'tapa7ad1b7c-8f']
2014-11-25 20:15:39.455 21778 TRACE neutron.agent.linux.ovs_lib Exit code: 1
2014-11-25 20:15:39.455 21778 TRACE neutron.agent.linux.ovs_lib Stdout: ''
2014-11-25 20:15:39.455 21778 TRACE neutron.agent.linux.ovs_lib Stderr: 'ovs-vsctl: no interface named tapa7ad1b7c-8f\n'
2014-11-25 20:15:39.455 21778 TRACE neutron.agent.linux.ovs_lib

and then multiple:

014-11-25 20:15:51.629 21778 ERROR neutron.agent.linux.ovs_lib [-] Unable to execute ['ovs-vsctl', '--timeout=10', 'get', 'Port', u'tapfa2fdc36-32', 'tag']. Exception:
Command: ['sudo', '/usr/local/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ovs-vsctl', '--timeout=10', 'get', 'Port', 'tapfa2fdc36-32', 'tag']
Exit code: 1
Stdout: ''
Stderr: 'ovs-vsctl: no row "tapfa2fdc36-32" in table Port\n'

[Jamie Lennox (jamielennox)]

Adding tempest - i really don't think it's a tempest issue.

[Matthew Treinish (treinish)]

This is not a tempest bug, neutron is returning a 500 because of an unhandled exception. If you look in the neutron logs you'll see a failure in the DB layer around the typing in Postgres. This failure should be fixed by this backport: https://review.openstack.org/#/c/137423/