yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1782421] Re: Port creation fails during concurrent deploys

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: OpenStack Infra <1782421@xxxxxxxxxxxxxxxxxx>
Date: Tue, 14 Aug 2018 09:19:18 -0000
Reply-to: Bug 1782421 <1782421@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Reviewed:  https://review.openstack.org/587373
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=e9a7ed8c63ec5bb0fdca3406c8b21071729dd09d
Submitter: Zuul
Branch:    master

commit e9a7ed8c63ec5bb0fdca3406c8b21071729dd09d
Author: ymadhavi@xxxxxxxxxx <ymadhavi@xxxxxxxxxx>
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


** Changed in: neutron
       Status: In Progress => Fix Released

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

Title:
  Port creation fails during concurrent deploys

Status in neutron:
  Fix Released

Bug description:
  
  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

To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/1782421/+subscriptions
References

[Bug 1782421] [NEW] Port creation fails during concurrent deploys
From: ymadhavi@xxxxxxxxxx, 2018-07-18