test_add_remove_router_interface_with_port_id failed in gate job

[Oleg Bondarev]

Traceback (most recent call last):
2014-02-05 10:27:00.973 | File "tempest/api/network/test_routers.py", line 101, in test_add_remove_router_interface_with_port_id
2014-02-05 10:27:00.973 | network_id=network['id'])
2014-02-05 10:27:00.973 | File "tempest/services/network/network_client_base.py", line 134, in _create
2014-02-05 10:27:00.974 | resp, body = self.post(uri, post_data)
2014-02-05 10:27:00.974 | File "tempest/services/network/network_client_base.py", line 63, in post
2014-02-05 10:27:00.974 | return self.rest_client.post(uri, body, headers)
2014-02-05 10:27:00.974 | File "tempest/common/rest_client.py", line 289, in post
2014-02-05 10:27:00.974 | return self.request('POST', url, headers, body)
2014-02-05 10:27:00.974 | File "tempest/common/rest_client.py", line 423, in request
2014-02-05 10:27:00.974 | resp, resp_body)
2014-02-05 10:27:00.974 | File "tempest/common/rest_client.py", line 516, in _error_checker
2014-02-05 10:27:00.974 | raise exceptions.ServerFault(message)
2014-02-05 10:27:00.974 | ServerFault: Got server fault
2014-02-05 10:27:00.974 | Details: {"NeutronError": "Request Failed: internal server error while processing your request."}

Console: http://logs.openstack.org/18/62318/2/gate/gate-tempest-dsvm-neutron-pg-isolated/5567cfe/console.html

Following was observed in q-svc:
2014-02-05 10:07:07.817 5891 ERROR neutron.api.v2.resource [req-4408860b-175b-44a7-bdbc-ed41d66c0937 None] show failed
2014-02-05 10:07:07.817 5891 TRACE neutron.api.v2.resource Traceback (most recent call last):
2014-02-05 10:07:07.817 5891 TRACE neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/resource.py", line 84, in resource
2014-02-05 10:07:07.817 5891 TRACE neutron.api.v2.resource result = method(request=request, **args)
2014-02-05 10:07:07.817 5891 TRACE neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/base.py", line 296, in show
2014-02-05 10:07:07.817 5891 TRACE neutron.api.v2.resource parent_id=parent_id),
2014-02-05 10:07:07.817 5891 TRACE neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/base.py", line 264, in _item
2014-02-05 10:07:07.817 5891 TRACE neutron.api.v2.resource obj = obj_getter(request.context, id, **kwargs)
2014-02-05 10:07:07.817 5891 TRACE neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/db/securitygroups_db.py", line 180, in get_security_group
2014-02-05 10:07:07.817 5891 TRACE neutron.api.v2.resource context, id), fields)
2014-02-05 10:07:07.817 5891 TRACE neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/db/securitygroups_db.py", line 194, in _get_security_group
2014-02-05 10:07:07.817 5891 TRACE neutron.api.v2.resource raise ext_sg.SecurityGroupNotFound(id=id)
2014-02-05 10:07:07.817 5891 TRACE neutron.api.v2.resource SecurityGroupNotFound: Security group 89f2b1df-2a09-4a17-b2ec-51f61215855d does not exist
2014-02-05 10:07:07.817 5891 TRACE neutron.api.v2.resource

[Eugene Nikanorov (enikanorov)]

The root cause is a relatively rare race condition happening when dhcp agent makes get_active_networks_info and at the same time network gets scheduled due to the first port being created.

[OpenStack Infra (hudson-openstack)]

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

[Eugene Nikanorov (enikanorov)]

Proper traceback:
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource Traceback (most recent call last):
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/resource.py", line 84, in resource
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource result = method(request=request, **args)
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/base.py", line 413, in create
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource obj)})
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/base.py", line 392, in notify
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource notifier_method)
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/base.py", line 274, in _send_dhcp_notification
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource self._dhcp_agent_notifier.notify(context, data, methodname)
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/rpc/agentnotifiers/dhcp_rpc_agent_api.py", line 153, in notify
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource self._notification(context, methodname, data, network_id)
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/rpc/agentnotifiers/dhcp_rpc_agent_api.py", line 71, in _notification
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource chosen_agents = plugin.schedule_network(adminContext, network)
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/db/agentschedulers_db.py", line 207, in schedule_network
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource self, context, created_network)
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/scheduler/dhcp_agent_scheduler.py", line 83, in schedule
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource self._schedule_bind_network(context, agent, network['id'])
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 447, in __exit__
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource self.rollback()
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 58, in __exit__
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource compat.reraise(exc_type, exc_value, exc_tb)
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 444, in __exit__
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource self.commit()
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 354, in commit
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource self._prepare_impl()
2014-02-05 10:13:33.087 5891 TRACE neutron.api.v2.resource File ...

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/71393
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=eed1b7cbdb00a3fbac9f19bab1a2d7366833b753
Submitter: Jenkins
Branch: master

commit eed1b7cbdb00a3fbac9f19bab1a2d7366833b753
Author: Eugene Nikanorov <email address hidden>
Date: Thu Feb 6 01:52:35 2014 +0400

    Fix race condition in network scheduling to dhcp agent

    Rarely dhcp agent rpc call get_active_networks_info() can interleave
    with network scheduling initiated by create.port.end notification.
    In this case scheduling raises and port creation returns 500.
    Need to synchronize on DhcpNetworkBindings table.

    Closes-Bug: #1276552
    Change-Id: I52d94a40772a99c7032dba15b200bf0f21362f93

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/havana
Review: https://review.openstack.org/72537