Port creation fails during concurrent deploys

[[e-mail]]

During concurrent deploy of 10 instances/virtual machines at a time, getting lot of errors in neutron server log saying
UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched.

(During single deploy with one nic/one port, 'network' revisions number in 'standardattributes' table is bumping up 6 times.)

So when multiple threads doing port creation on the same network, lot of threads getting the issue.
Following are few logs collected, while network revision number was read by two requests as 46568, but one of the request updated it to 46569 successfully and the other request continuously trying to update it and failing and request ended up with 500.

Request1
2018-07-18 04:41:05.144 26476 INFO neutron.db.segments_db [req-73f8203a-57fb-4c00-acdd-124ade6f2c21 - - - - -] DEBUG: getting network segments {'network_id': [u'a411c8d6-fd9b-4c44-adf4-71a08d4474ad'], 'is_dynamic': False}
2018-07-18 04:41:05.155 26476 INFO sqlalchemy.engine.base.Engine [req-73f8203a-57fb-4c00-acdd-124ade6f2c21 - - - - -] UPDATE standardattributes SET revision_number=%s, updated_at=%s WHERE standardattributes.id = %s AND standardattributes.revision_number = %s
2018-07-18 04:41:05.201 26476 INFO sqlalchemy.engine.base.Engine [req-73f8203a-57fb-4c00-acdd-124ade6f2c21 - - - - -] (46569L, datetime.datetime(2018, 7, 18, 9, 41, 5), 6L, 46568L)

2018-07-18 04:41:09.844 26473 INFO sqlalchemy.engine.base.Engine [req-73f8203a-57fb-4c00-acdd-124ade6f2c21 - - - - -] UPDATE standardattributes SET updated_at=%s WHERE standardattributes.id = %s AND standardattributes.revision_number = %s
2018-07-18 04:41:09.845 26473 INFO sqlalchemy.engine.base.Engine [req-73f8203a-57fb-4c00-acdd-124ade6f2c21 - - - - -] (46570L, datetime.datetime(2018, 7, 18, 9, 41, 9), 6L, 46569L)
2018-07-18 04:41:10.029 26473 INFO sqlalchemy.engine.base.Engine [req-73f8203a-57fb-4c00-acdd-124ade6f2c21 - - - - -] SAVEPOINT sa_savepoint_1
2018-07-18 04:41:10.031 26473 INFO sqlalchemy.engine.base.Engine [req-73f8203a-57fb-4c00-acdd-124ade6f2c21 - - - - -] ()
2018-07-18 04:41:10.039 26473 INFO sqlalchemy.engine.base.Engine [req-73f8203a-57fb-4c00-acdd-124ade6f2c21 - - - - -] SAVEPOINT sa_savepoint_2
2018-07-18 04:41:10.040 26473 INFO sqlalchemy.engine.base.Engine [req-73f8203a-57fb-4c00-acdd-124ade6f2c21 - - - - -] ()
2018-07-18 04:41:10.048 26473 INFO sqlalchemy.engine.base.Engine [req-73f8203a-57fb-4c00-acdd-124ade6f2c21 - - - - -] SELECT networksegments.id AS networksegments_id, networksegments.network_id AS networksegments_network_id, networksegments.network_type AS networksegments_network_type, networksegments.physical_network AS networksegments_physical_network, networksegments.segmentation_id AS networksegments_segmentation_id, networksegments.is_dynamic AS networksegments_is_dynamic, networksegments.segment_index AS networksegments_segment_index, networksegments.name AS networksegments_name, networksegments.standard_attr_id AS networksegments_standard_attr_id, standardattributes_1.id AS standardattributes_1_id, standardattributes_1.resource_type AS standardattributes_1_resource_type, standardattributes_1.description AS standardattributes_1_description, standardattributes_1.revision_number AS standardattributes_1_revision_number, standardattributes_1.created_at AS standardattributes_1_created_at, standardattributes_1.updated_at AS standardattributes_1_updated_at

Request2
018-07-18 04:41:06.478 26456 DEBUG sqlalchemy.engine.base.Engine [req-376bd726-7a8a-425b-80df-1c50ad49c404 0688b01e6439ca32d698d20789d52169126fb41fb1a4ddafcebb97d854e836c9 cf344846a90a4d278f97dcdb7b01fbe6 - default default] Row ('cf344846a90a4d278f97dcdb7b01fbe6', 'a411c8d6-fd9b-4c44-adf4-71a08d4474ad', 'sdn120', 'ACTIVE', 1, None, '[]', 1500L, 6L, 6L, 'networks', '', 46569L, datetime.datetime(2018, 7, 5, 16, 57, 48), datetime.datetime(2018, 7, 18, 9, 41, 5), 'a411c8d6-fd9b-4c44-adf4-71a08d4474ad', 0, None, None, None, None, 'a411c8d6-fd9b-4c44-adf4-71a08d4474ad', 1) process_rows /usr/lib64/python2.7/site-packages/sqlalchemy/engine/result.py:1094
.....
2018-07-18 04:42:21.787 26456 INFO neutron.db.segments_db [req-376bd726-7a8a-425b-80df-1c50ad49c404 0688b01e6439ca32d698d20789d52169126fb41fb1a4ddafcebb97d854e836c9 cf344846a90a4d278f97dcdb7b01fbe6 - default default] DEBUG: getting network segments {'network_id': [u'a411c8d6-fd9b-4c44-adf4-71a08d4474ad'], 'is_dynamic': False}
2018-07-18 04:42:21.798 26456 INFO sqlalchemy.engine.base.Engine [req-376bd726-7a8a-425b-80df-1c50ad49c404 0688b01e6439ca32d698d20789d52169126fb41fb1a4ddafcebb97d854e836c9 cf344846a90a4d278f97dcdb7b01fbe6 - default default] UPDATE standardattributes SET revision_number=%s, updated_at=%s WHERE standardattributes.id = %s AND standardattributes.revision_number = %s
2018-07-18 04:42:21.799 26456 INFO sqlalchemy.engine.base.Engine [req-376bd726-7a8a-425b-80df-1c50ad49c404 0688b01e6439ca32d698d20789d52169126fb41fb1a4ddafcebb97d854e836c9 cf344846a90a4d278f97dcdb7b01fbe6 - default default] (46590L, datetime.datetime(2018, 7, 18, 9, 42, 21), 6L, 46589L)
2018-07-18 04:42:21.802 26456 INFO sqlalchemy.engine.base.Engine [req-376bd726-7a8a-425b-80df-1c50ad49c404 0688b01e6439ca32d698d20789d52169126fb41fb1a4ddafcebb97d854e836c9 cf344846a90a4d278f97dcdb7b01fbe6 - default default] ROLLBACK
2018-07-18 04:42:21.815 26456 ERROR oslo_db.api [req-376bd726-7a8a-425b-80df-1c50ad49c404 0688b01e6439ca32d698d20789d52169126fb41fb1a4ddafcebb97d854e836c9 cf344846a90a4d278f97dcdb7b01fbe6 - default default] DB exceeded retry limit.: StaleDataError: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched.
2018-07-18 04:42:21.834 26456 ERROR neutron.pecan_wsgi.hooks.translation [req-376bd726-7a8a-425b-80df-1c50ad49c404 0688b01e6439ca32d698d20789d52169126fb41fb1a4ddafcebb97d854e836c9 cf344846a90a4d278f97dcdb7b01fbe6 - default default] POST failed.: StaleDataError: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched.
20

2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 1280, in create_port
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api result, mech_context = self._create_port_db(context, port)
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 1255, in _create_port_db
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api network = self.get_network(context, result['network_id'])
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 161, in wrapped
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api return method(*args, **kwargs)
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 1002, in get_network
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api self.type_manager.extend_network_dict_provider(context, net_data)
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/managers.py", line 155, in extend_network_dict_provider
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api return self.extend_networks_dict_provider(context, [network])
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/managers.py", line 159, in extend_networks_dict_provider
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api net_segments = segments_db.get_networks_segments(context, ids)
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/db/segments_db.py", line 79, in get_networks_segments
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api objs = network_obj.NetworkSegment.get_objects(context, **filters)
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/objects/network.py", line 157, in get_objects
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api **kwargs)
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/objects/base.py", line 574, in get_objects
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api with cls.db_context_reader(context):
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api return self.gen.next()
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 202, in autonested_transaction
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api session_context = sess.begin(nested=True)
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 798, in begin
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api nested=nested)
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 299, in _begin
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api self.session, self, nested=nested)
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 218, in __init__
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api self._take_snapshot()
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 327, in _take_snapshot
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api self.session.flush()
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 2139, in flush
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api self._flush(objects)
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 2259, in _flush
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api transaction.rollback(_capture_exception=True)
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 66, in __exit__
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api compat.reraise(exc_type, exc_value, exc_tb)
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 2223, in _flush
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api flush_context.execute()
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 389, in execute
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api rec.execute(self)
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 548, in execute
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api uow
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 177, in save_obj
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api mapper, table, update)
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 760, in _emit_update_statements
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api (table.description, len(records), rows))
2018-07-17 09:23:31.409 20276 ERROR oslo_db.api StaleDataError: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched.

2018-07-18 04:42:22.139 26456 INFO neutron.wsgi [req-376bd726-7a8a-425b-80df-1c50ad49c404 0688b01e6439ca32d698d20789d52169126fb41fb1a4ddafcebb97d854e836c9 cf344846a90a4d278f97dcdb7b01fbe6 - default default] 9.5.36.62,127.0.0.1 "POST /v2.0/ports HTTP/1.1" status: 500 len: 382 time: 130.0422821

Unable to scale beyond 100 VM ,as port creation is failing even after increasing network_allocate_retries to 10

[LIU Yulong (dragon889)]

We meet such issue too.

And something similar to your changing, I'm trying to fix such DB retry issue here:
https://bugs.launchpad.net/neutron/+bug/1777968

[Lujin Luo (lujin)]

This bug looks to me as a duplicate of 1777968 as LIU replied.

@ymadhavi, could you please check if LIU's patch will ease your issue? If so, I will mark it as duplicate.

[[e-mail] (ymadhavi)]

I tried to apply both patches

https://review.openstack.org/#/c/583527/
https://review.openstack.org/#/c/577739/

But I do not see much improvement. Still scale test is failing after reaching 120 VM count and now getting AMQP time outs as threads started waiting more time than previous.

My environment is ,stable/queens), 5 compute nodes, 1 neutron server with 10 threads, scale to 500 virtual machines concurrently with 10 thread.

I see that revision_plugin is called before session.flush() and it is trying to bump revisions of all objects in a session if session.dirty() is true. But network object is not yet all modified during port creation but it is there in the session, so network object also getting new revision each time when session.flush() is done, which is actually causing threads to end up with old revision network object and they end up with 500 error after said number of retries.

I tried something around like added one more check at

https://github.com/openstack/neutron/blob/master/neutron/services/revisions/revision_plugin.py#L48

if session.is_modiified(obj) and isinstance(obj, standard_attr.HasStandardAttributes):
then bump revision.

Though it adds one additional expensive operation but still it gives more accuracy on whether the object is modified or not.

With this workaround I am able to scale successfully upto 500 VM with out any errors in neutron.

[Lujin Luo (lujin)]

From what I understand the implementation of revision numbers, part of the reason we bump network's revision number, when ports/subnets are modified (even though network itself is not directly modified) is to prevent race conditions.

We had a bug reported when 2 concurrent threads trying to create overlapping subnets in one network, we couldn't prevent it in db layer. But with revision number implemented, such concurrency can be detected and prevented. Thus, my concern is that the change mentioned in your last comment may let us lose that.

[[e-mail] (ymadhavi)]

If we need to update network revision on update of port/subnet then can we update as part of _bump_related_revisions (revises_on_change ), so that network is revised only when the particular object is modified. But right now all session.flush() revising network.

[YAMAMOTO Takashi (yamamoto)]

i see at least two issues
- the retry mechanism doesn't scale (fairness issue?)
- i guess 500 is not the best status for the situation

[LIU Yulong (dragon889)]

We can see some "UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched" logs everyday.

2018-07-30 10:59:46.447 108317 DEBUG neutron.db.api [req-48c68b31-f5f1-4c22-ac9a-fa643b8cb099 - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:126
2018-07-30 10:59:46.464 108315 DEBUG neutron.db.api [req-138448d3-88f1-476e-b4cd-80af272445da - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:126
2018-07-30 11:33:05.585 108322 ERROR neutron.plugins.ml2.managers StaleDataError: UPDATE statement on table 'ml2_port_bindings' expected to update 1 row(s); 0 were matched.
2018-07-30 11:33:05.586 108322 DEBUG neutron.db.api [req-452d345f-8fb3-4816-ae19-0126766c822b - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'ml2_port_bindings' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:126
2018-07-30 11:33:05.611 108325 ERROR neutron.plugins.ml2.managers StaleDataError: UPDATE statement on table 'ml2_port_bindings' expected to update 1 row(s); 0 were matched.
2018-07-30 11:33:05.612 108325 DEBUG neutron.db.api [req-9cf3baa0-457e-4402-bec2-d3e6a64225b7 - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'ml2_port_bindings' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:126
2018-07-30 11:33:05.653 108324 ERROR neutron.plugins.ml2.managers StaleDataError: UPDATE statement on table 'ml2_port_bindings' expected to update 1 row(s); 0 were matched.
2018-07-30 11:33:05.654 108324 DEBUG neutron.db.api [req-f53c8241-d9af-45a7-9a61-90be7e13f5c1 - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'ml2_port_bindings' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:126
2018-07-30 11:33:06.719 108324 DEBUG neutron.db.api [req-f53c8241-d9af-45a7-9a61-90be7e13f5c1 - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:126
2018-07-30 11:33:06.720 108325 DEBUG neutron.db.api [req-9cf3baa0-457e-4402-bec2-d3e6a64225b7 - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:126
2018-07-30 11:33:07.389 108324 DEBUG neutron.db.api [req-f53c8241-d9af-45a7-9a61-90be7e13f5c1 - - - - -] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. wrapped /usr/lib/python2.7/site-packages/neutron/db/api.py:126
2018-07-30 17:34:16.531 108317 DEBUG neutron.db.api [req-9ff03183-9b90-4d07-a83a-1f6d7c021434 - - - - -] Retry wrapper got retriable exception: UPDATE statement on tab...

[OpenStack Infra (hudson-openstack)]

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

[[e-mail] (ymadhavi)]

I tried to update network revision only when there is an IPAMAloocation change, using revises_on_change in that case network will get a new revision when there is a new IPAMAllocation(ip) , also Subnet model already has revises_on_change for 'network', so when there is a change in subnet it will be handled.

With these changes and above mentione revision_lugin check I am able to achieve 500 VM scale target with 2 VM deploy failed time out errors due to 'standardattributes' update issue.

Also proposed my change here.

https://review.openstack.org/#/c/587373/

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/587373
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=e9a7ed8c63ec5bb0fdca3406c8b21071729dd09d
Submitter: Zuul
Branch: master

commit e9a7ed8c63ec5bb0fdca3406c8b21071729dd09d
Author: <email address hidden> <email address hidden>
Date: Tue Jul 31 06:16:09 2018 -0400

    Update network revision only when it needs

    Basically, in case of concurrent requests creating ports
    on *one* network, only one request succeeds, other requests
    mostly getting 'standardattribute' update error as network
    revision_number changed about 8 times for all port updates.

    This patch increases network revision_number in database,
    only when a port is created in a network, instead of each
    update on port.

    Change-Id: Idffb4edda616677b9b071644d3835c85052091a5
    Closes-Bug: #1782421

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/rocky
Review: https://review.openstack.org/591599

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/queens
Review: https://review.openstack.org/591600

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/pike
Review: https://review.openstack.org/591601

[OpenStack Infra (hudson-openstack)]

Change abandoned by Vlad Gusev (<email address hidden>) on branch: stable/rocky
Review: https://review.openstack.org/591599

[OpenStack Infra (hudson-openstack)]

Change abandoned by Vlad Gusev (<email address hidden>) on branch: stable/queens
Review: https://review.openstack.org/591600

[OpenStack Infra (hudson-openstack)]

Change abandoned by Vlad Gusev (<email address hidden>) on branch: stable/pike
Review: https://review.openstack.org/591601

[Miguel Lavalle (minsel)]

During the PTG we discussed the possibility of adopting the new engine facade in parts of the code relevant to this bug to see if it helps

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/neutron 14.0.0.0b1 development milestone.