yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1398446] [NEW] Novacompute failed to detel VM port with DVR

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Zengfa Gao <zengfa.gao@xxxxxx>
Date: Tue, 02 Dec 2014 16:23:23 -0000
Reply-to: Bug 1398446 <1398446@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

This defect is hard to reproduce, only happens when I have more than 3
compute node with DVR enabled.

With the following script, run several times, I can see one VM in ERROR
state.


neutron net-create demo-net
netdemoid=$(neutron net-list | awk '{if($4=="'demo-net'"){print $2;}}')
neutron subnet-create demo-net 10.100.100.0/24 --name demo-subnet
subnetdemoid=$(neutron subnet-list | awk '{if($4=="'demo-subnet'"){print $2;}}')
neutron router-create demo-router
routerdemoid=$(neutron router-list | awk '{if($4=="'demo-router'"){print $2;}}')

exnetid=$(neutron net-list | awk '{if($4=="'ext-net'"){print $2;}}')
for i in `seq 1 10`; do
    #boot vm, and create floating ip
    nova boot --image cirros --flavor m1.tiny --nic net-id=$netdemoid cirrosdemo${i}
    cirrosdemoid[i]=$(nova list | awk '{if($4=="'cirrosdemo${i}'"){print $2;}}')
    output=$(neutron floatingip-create $exnetid)
    echo $output
    floatipid[i]=$(echo "$output" | awk '{if($2=="id"){print $4;}}')
    floatip[i]=$(echo "$output" | awk '{if($2=="floating_ip_address"){print $4;}}')a
done

# Setup router
neutron router-gateway-set $routerdemoid $exnetid
neutron router-interface-add demo-router $subnetdemoid
#wait for VM to be running
sleep 30

for i in `seq 1 10`; do
    cirrosfix=$(nova list | awk '{if($4=="'cirrosdemo${i}'"){print $12;}}')
    cirrosfixip=${cirrosfix#*=}
    output=$(neutron port-list | grep ${cirrosfixip})
    echo $output
    portid=$(echo "$output" | awk '{print $2;}')
    neutron floatingip-associate --fixed-ip-address $cirrosfixip ${floatipid[i]} $portid
    neutron floatingip-delete ${floatipid[i]}
    nova delete ${cirrosdemoid[i]}
done


neutron router-interface-delete demo-router $subnetdemoid
neutron router-gateway-clear demo-router $netdemoid
neutron router-delete demo-router
neutron subnet-delete $subnetdemoid
neutron net-delete $netdemoid

Looking at log file:
2014-11-20 17:25:56.258 31042 DEBUG neutron.openstack.common.lockutils [req-6eabf07e-2fe4-4960-89ca-f0ac3f04f7a5 None] Got semaphore "db-access" lock /opt/stack/venvs/openstack/local/lib/python2.7/site-packages/neutron/openstack/common/lockutils.py:168
2014-11-20 17:25:56.424 31042 ERROR neutron.api.v2.resource [req-6eabf07e-2fe4-4960-89ca-f0ac3f04f7a5 None] delete failed
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource Traceback (most recent call last):
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/neutron/api/v2/resource.py", line 87, in resource
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource result = method(request=request, **args)
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/neutron/api/v2/base.py", line 476, in delete
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource obj_deleter(request.context, id, **kwargs)
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 1036, in delete_port
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource router_info = l3plugin.dvr_deletens_if_no_vm(context, id)
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/neutron/db/l3_dvrscheduler_db.py", line 195, in dvr_deletens_if_no_vm
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource port_host)
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/neutron/db/agents_db.py", line 136, in _get_agent_by_type_and_host
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource Agent.host == host).one()
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2369, in one
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource ret = list(self)
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2411, in _iter_
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource self.session._autoflush()
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1198, in _autoflush
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource self.flush()
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1919, in flush
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource self._flush(objects)
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2037, in _flush
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource transaction.rollback(_capture_exception=True)
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in _exit_
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource compat.reraise(exc_type, exc_value, exc_tb)
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2001, in _flush
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource flush_context.execute()
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 372, in execute
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource rec.execute(self)
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 526, in execute
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource uow
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 60, in save_obj
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource mapper, table, update)
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 536, in _emit_update_statements
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource (table.description, len(update), rows))
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource StaleDataError: UPDATE statement on table 'ml2_dvr_port_bindings' expected to update 1 row(s); 0 were matched.
2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource
2014-11-20 17:25:56.427 31042 INFO neutron.wsgi [req-6eabf07e-2fe4-4960-89ca-f0ac3f04f7a5 None] 10.23.32.135 - - [20/Nov/2014 17:25:56] "DELETE /v2.0/ports/83f2d987-0ab7-4479-8c97-7ab7b758a2dc.json HTTP/1.1" 500 296 0.235463


The problem could be some race condition. The code l3_devscheduler_db.py
>From line 158, got_dvr_routers_by_portid to line 193 get_agent_by_type_and_host, there are several calls.
If the port was there when code on 158. Another thread comes in the middle, delete the port. Line 193 will fail because the entry was not there anymore.
Both "neutron floatingip-delete" and "nova delete" can delete the port.

I think if we move l3_devscheduler_db.py, line 193:
            agent = self._get_agent_by_type_and_host(context,
                                                     q_const.AGENT_TYPE_L3,
                                                     port_host)
to line 164

It should resolve the problem.

** Affects: neutron
     Importance: Undecided
         Status: New

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

Title:
  Novacompute failed to detel VM port with DVR

Status in OpenStack Neutron (virtual network service):
  New

Bug description:
  This defect is hard to reproduce, only happens when I have more than 3
  compute node with DVR enabled.

  With the following script, run several times, I can see one VM in
  ERROR state.

  
  neutron net-create demo-net
  netdemoid=$(neutron net-list | awk '{if($4=="'demo-net'"){print $2;}}')
  neutron subnet-create demo-net 10.100.100.0/24 --name demo-subnet
  subnetdemoid=$(neutron subnet-list | awk '{if($4=="'demo-subnet'"){print $2;}}')
  neutron router-create demo-router
  routerdemoid=$(neutron router-list | awk '{if($4=="'demo-router'"){print $2;}}')

  exnetid=$(neutron net-list | awk '{if($4=="'ext-net'"){print $2;}}')
  for i in `seq 1 10`; do
      #boot vm, and create floating ip
      nova boot --image cirros --flavor m1.tiny --nic net-id=$netdemoid cirrosdemo${i}
      cirrosdemoid[i]=$(nova list | awk '{if($4=="'cirrosdemo${i}'"){print $2;}}')
      output=$(neutron floatingip-create $exnetid)
      echo $output
      floatipid[i]=$(echo "$output" | awk '{if($2=="id"){print $4;}}')
      floatip[i]=$(echo "$output" | awk '{if($2=="floating_ip_address"){print $4;}}')a
  done

  # Setup router
  neutron router-gateway-set $routerdemoid $exnetid
  neutron router-interface-add demo-router $subnetdemoid
  #wait for VM to be running
  sleep 30

  for i in `seq 1 10`; do
      cirrosfix=$(nova list | awk '{if($4=="'cirrosdemo${i}'"){print $12;}}')
      cirrosfixip=${cirrosfix#*=}
      output=$(neutron port-list | grep ${cirrosfixip})
      echo $output
      portid=$(echo "$output" | awk '{print $2;}')
      neutron floatingip-associate --fixed-ip-address $cirrosfixip ${floatipid[i]} $portid
      neutron floatingip-delete ${floatipid[i]}
      nova delete ${cirrosdemoid[i]}
  done

  
  neutron router-interface-delete demo-router $subnetdemoid
  neutron router-gateway-clear demo-router $netdemoid
  neutron router-delete demo-router
  neutron subnet-delete $subnetdemoid
  neutron net-delete $netdemoid

  Looking at log file:
  2014-11-20 17:25:56.258 31042 DEBUG neutron.openstack.common.lockutils [req-6eabf07e-2fe4-4960-89ca-f0ac3f04f7a5 None] Got semaphore "db-access" lock /opt/stack/venvs/openstack/local/lib/python2.7/site-packages/neutron/openstack/common/lockutils.py:168
  2014-11-20 17:25:56.424 31042 ERROR neutron.api.v2.resource [req-6eabf07e-2fe4-4960-89ca-f0ac3f04f7a5 None] delete failed
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource Traceback (most recent call last):
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/neutron/api/v2/resource.py", line 87, in resource
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource result = method(request=request, **args)
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/neutron/api/v2/base.py", line 476, in delete
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource obj_deleter(request.context, id, **kwargs)
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 1036, in delete_port
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource router_info = l3plugin.dvr_deletens_if_no_vm(context, id)
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/neutron/db/l3_dvrscheduler_db.py", line 195, in dvr_deletens_if_no_vm
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource port_host)
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/neutron/db/agents_db.py", line 136, in _get_agent_by_type_and_host
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource Agent.host == host).one()
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2369, in one
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource ret = list(self)
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2411, in _iter_
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource self.session._autoflush()
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1198, in _autoflush
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource self.flush()
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1919, in flush
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource self._flush(objects)
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2037, in _flush
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource transaction.rollback(_capture_exception=True)
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in _exit_
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource compat.reraise(exc_type, exc_value, exc_tb)
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2001, in _flush
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource flush_context.execute()
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 372, in execute
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource rec.execute(self)
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 526, in execute
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource uow
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 60, in save_obj
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource mapper, table, update)
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource File "/opt/stack/venvs/openstack/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 536, in _emit_update_statements
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource (table.description, len(update), rows))
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource StaleDataError: UPDATE statement on table 'ml2_dvr_port_bindings' expected to update 1 row(s); 0 were matched.
  2014-11-20 17:25:56.424 31042 TRACE neutron.api.v2.resource
  2014-11-20 17:25:56.427 31042 INFO neutron.wsgi [req-6eabf07e-2fe4-4960-89ca-f0ac3f04f7a5 None] 10.23.32.135 - - [20/Nov/2014 17:25:56] "DELETE /v2.0/ports/83f2d987-0ab7-4479-8c97-7ab7b758a2dc.json HTTP/1.1" 500 296 0.235463

  
  The problem could be some race condition. The code l3_devscheduler_db.py
  From line 158, got_dvr_routers_by_portid to line 193 get_agent_by_type_and_host, there are several calls.
  If the port was there when code on 158. Another thread comes in the middle, delete the port. Line 193 will fail because the entry was not there anymore.
  Both "neutron floatingip-delete" and "nova delete" can delete the port.

  I think if we move l3_devscheduler_db.py, line 193:
              agent = self._get_agent_by_type_and_host(context,
                                                       q_const.AGENT_TYPE_L3,
                                                       port_host)
  to line 164

  It should resolve the problem.

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

[Bug 1398446] Re: Nova compute failed to delete VM port with DVR
From: Swaminathan Vasudevan, 2015-04-01
[Bug 1398446] [NEW] Novacompute failed to detel VM port with DVR
From: Zengfa Gao, 2014-12-02
References

[Bug 1398446] [NEW] Novacompute failed to detel VM port with DVR
From: Zengfa Gao, 2014-12-02