DELETE /v2.0/ports/uuid.json causes SQL error in log

[jason bishop]

I'm running 20 tempest test_server_basic_ops scenario tests at same time and after a few iterations it will fail during teardown with this stack:

2015-05-04 08:57:25.769 20904 ERROR neutron.api.v2.resource [req-15065032-6513-4433-81b8-89bc53ea8c6a None] delete failed
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource Traceback (most recent call last):
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/api/v2/resource.py", line 87, in resource
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource result = method(request=request, **args)
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/api/v2/base.py", line 476, in delete
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource obj_deleter(request.context, id, **kwargs)
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/plugins/ml2/plugin.py", line 1019, in delete_port
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource context, id, do_notify=False)
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/db/l3_dvr_db.py", line 203, in disassociate_floatingips
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource do_notify=do_notify)
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/db/l3_db.py", line 1185, in disassociate_floatingips
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource context, port_id)
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/db/l3_db.py", line 915, in disassociate_floatingips
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource 'router_id': None})
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 470, in __exit__
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource self.rollback()
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource compat.reraise(exc_type, exc_value, exc_tb)
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 467, in __exit__
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource self.commit()
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 377, in commit
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource self._prepare_impl()
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 357, in _prepare_impl
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource self.session.flush()
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1919, in flush
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource self._flush(objects)
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2037, in _flush
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource transaction.rollback(_capture_exception=True)
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource compat.reraise(exc_type, exc_value, exc_tb)
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2001, in _flush
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource flush_context.execute()
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 372, in execute
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource rec.execute(self)
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 526, in execute
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource uow
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 60, in save_obj
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource mapper, table, update)
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 536, in _emit_update_statements
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource (table.description, len(update), rows))
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource StaleDataError: UPDATE statement on table 'floatingips' expected to update 1 row(s); 0 were matched.
2015-05-04 08:57:25.769 20904 TRACE neutron.api.v2.resource
2015-05-04 08:57:25.776 20905 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 172.17.206.35
2015-05-04 08:57:25.778 20904 INFO neutron.wsgi [req-15065032-6513-4433-81b8-89bc53ea8c6a None] 172.17.206.34 - - [04/May/2015 08:57:25] "DELETE /v2.0/ports/8b204abc-ac3d-46f3-886e-1688467f3a73.json HTTP/1.1" 500 359 0.600022

[jason bishop (jason-bishop)]

I was suspicious this is just artifact of race with floatingip dissassociate so I made this small change and ran tests again. running 30 test_server_basic_ops same time for 7hours only had a few failures, so i think it is likely the path through the code which results in this error does not cause a problem with the test.

diff -u /usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py{~,}
--- /usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py~ 2014-07-22 13:54:20.000000000 -0700
+++ /usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py 2015-05-04 12:15:46.589046946 -0700
@@ -530,10 +530,13 @@

     if connection.dialect.supports_sane_rowcount:
         if rows != len(update):
- raise orm_exc.StaleDataError(
- "UPDATE statement on table '%s' expected to "
- "update %d row(s); %d were matched." %
- (table.description, len(update), rows))
+# raise orm_exc.StaleDataError(
+# "UPDATE statement on table '%s' expected to "
+# "update %d row(s); %d were matched." %
+# (table.description, len(update), rows))
+ util.warn("UPDATE statement on table '%s' expected to "
+ "update %d row(s); %d were matched." %
+ (table.description, len(update), rows))

     elif needs_version_id:
         util.warn("Dialect %s does not support updated rowcount "

[Armando Migliaccio (armando-migliaccio)]

This bug is > 240 days without activity. We are unsetting assignee and milestone and setting status to Incomplete in order to allow its expiry in 60 days.

If the bug is still valid, then update the bug status.

[Launchpad Janitor (janitor)]

[Expired for neutron because there has been no activity for 60 days.]