rally sla failure / internal error on load

[YAMAMOTO Takashi]

On networking-midonet gate, for following scenarios, max_seconds_per_iteration validation is failing miserably.
These scenarios are currently disabled for an unrelated issue [1] but there is an attempt to revive it. [2]
IIRC, these scenarios used to work. I don't remember when it was though. (Maybe newton timeframe)

NetworkPlugin.create_ports
NetworkPlugin.create_routers
NetworkPlugin.create_subnets
NetworkPlugin.create_subnets_routers_interfaces

[1] bug 1670577
[2] https://review.openstack.org/#/c/492374/

It's probably due to retriable exceptions like the following due to contentions.

eg. http://logs.openstack.org/74/492374/3/check/gate-networking-midonet-rally-dsvm-ml2-ubuntu-xenial/d1aa9b9/logs/screen-q-svc.txt.gz

Aug 14 06:08:16.188519 ubuntu-xenial-citycloud-kna1-10421138 neutron-server[14391]: DEBUG neutron.db.api [None req-6c986099-0e8d-4181-a488-c73d348f2ef5 c_rally_1a0448a8_y9LQrXNX c_rally_1a0448a8_QH0dDRH4] Retry wrapper got retriable exception: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched. {{(pid=14479) wrapped /opt/stack/new/neutron/neutron/db/api.py:129}}

Aug 14 05:46:27.279500 ubuntu-xenial-citycloud-kna1-10421138 neutron-server[14391]: DEBUG neutron.db.api [None req-6134c462-06e4-493f-8ff1-9b206dfda3dd c_rally_edf0ce7f_CaBvNcQe c_rally_edf0ce7f_ONZDWSHE] Retry wrapper got retriable exception: Failed to create a duplicate IpamAllocation: for attribute(s) ['PRIMARY'] with value(s) 2.224.0.54-29522f59-ea05-4904-b034-fa3555da8ade {{(pid=14479) wrapped /opt/stack/new/neutron/neutron/db/api.py:129}}

Aug 14 05:39:37.960137 ubuntu-xenial-citycloud-kna1-10421138 neutron-server[14391]: DEBUG neutron.db.api [None req-f3ecc8f3-2c7a-4b3c-ac8c-abe2766e36f4 c_rally_6464adb0_pXKwRzJz c_rally_6464adb0_uyMbSZqP] Retry wrapper got retriable exception: Failed to create a duplicate DefaultSecurityGroup: for attribute(s) ['PRIMARY'] with value(s) bc3b6a26a56646e7b098b9419d17c0d1 {{(pid=14480) wrapped /opt/stack/new/neutron/neutron/db/api.py:129}}

Even without max_seconds_per_iteration, it sometimes times out,
or causes internal error reaching to the retry limit.

eg. http://logs.openstack.org/74/492374/4/check/gate-networking-midonet-rally-dsvm-ml2-ubuntu-xenial/5f6c27d/logs/screen-q-svc.txt.gz?level=TRACE

Aug 14 13:54:59.896408 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api [None req-c66e03cb-f36a-494b-9f83-fcb51dd0a420 c_rally_732dd379_PVser3Et c_rally_732dd379_0ywBv9Oh] DB exceeded retry limit.: StaleDataError: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched.
Aug 14 13:54:59.896764 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api Traceback (most recent call last):
Aug 14 13:54:59.896968 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/usr/local/lib/python2.7/dist-packages/oslo_db/api.py", line 138, in wrapper
Aug 14 13:54:59.897135 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api return f(*args, **kwargs)
Aug 14 13:54:59.897300 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/opt/stack/new/neutron/neutron/db/api.py", line 129, in wrapped
Aug 14 13:54:59.897465 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api LOG.debug("Retry wrapper got retriable exception: %s", e)
Aug 14 13:54:59.897653 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Aug 14 13:54:59.897819 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api self.force_reraise()
Aug 14 13:54:59.897970 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
Aug 14 13:54:59.898135 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api six.reraise(self.type_, self.value, self.tb)
Aug 14 13:54:59.898300 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/opt/stack/new/neutron/neutron/db/api.py", line 125, in wrapped
Aug 14 13:54:59.898458 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api return f(*dup_args, **dup_kwargs)
Aug 14 13:54:59.898621 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py", line 1013, in delete_subnet
Aug 14 13:54:59.898792 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api self.ipam.delete_subnet(context, id)
Aug 14 13:54:59.898948 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/opt/stack/new/neutron/neutron/db/ipam_pluggable_backend.py", line 162, in delete_subnet
Aug 14 13:54:59.899122 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api ipam_driver.remove_subnet(subnet_id)
Aug 14 13:54:59.899283 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/opt/stack/new/neutron/neutron/ipam/drivers/neutrondb_ipam/driver.py", line 317, in remove_subnet
Aug 14 13:54:59.899439 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api subnet_id)
Aug 14 13:54:59.899595 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/opt/stack/new/neutron/neutron/ipam/drivers/neutrondb_ipam/db_api.py", line 68, in delete
Aug 14 13:54:59.899786 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api neutron_subnet_id=neutron_subnet_id)
Aug 14 13:54:59.899962 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/opt/stack/new/neutron/neutron/objects/base.py", line 512, in delete_objects
Aug 14 13:54:59.900125 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api context, cls.db_model, **cls.modify_fields_to_db(kwargs))
Aug 14 13:54:59.904444 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/opt/stack/new/neutron/neutron/objects/db/api.py", line 116, in delete_objects
Aug 14 13:54:59.904812 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api db_objs = get_objects(context, model, **kwargs)
Aug 14 13:54:59.904985 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/opt/stack/new/neutron/neutron/objects/db/api.py", line 53, in get_objects
Aug 14 13:54:59.905160 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api **(_pager.to_kwargs(context, model) if _pager else {}))
Aug 14 13:54:59.905333 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/opt/stack/new/neutron/neutron/db/_model_query.py", line 292, in get_collection
Aug 14 13:54:59.905499 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api for c in query
Aug 14 13:54:59.905680 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2854, in __iter__
Aug 14 13:54:59.905843 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api self.session._autoflush()
Aug 14 13:54:59.906008 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1397, in _autoflush
Aug 14 13:54:59.906172 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api self.flush()
Aug 14 13:54:59.906326 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2171, in flush
Aug 14 13:54:59.906495 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api self._flush(objects)
Aug 14 13:54:59.906674 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2291, in _flush
Aug 14 13:54:59.906814 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api transaction.rollback(_capture_exception=True)
Aug 14 13:54:59.906946 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 66, in __exit__
Aug 14 13:54:59.907093 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api compat.reraise(exc_type, exc_value, exc_tb)
Aug 14 13:54:59.907256 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2255, in _flush
Aug 14 13:54:59.907416 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api flush_context.execute()
Aug 14 13:54:59.907607 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 389, in execute
Aug 14 13:54:59.908653 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api rec.execute(self)
Aug 14 13:54:59.909744 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 548, in execute
Aug 14 13:54:59.910728 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api uow
Aug 14 13:54:59.910902 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 177, in save_obj
Aug 14 13:54:59.911064 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api mapper, table, update)
Aug 14 13:54:59.911219 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 760, in _emit_update_statements
Aug 14 13:54:59.911373 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api (table.description, len(records), rows))
Aug 14 13:54:59.911623 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api StaleDataError: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched.
Aug 14 13:54:59.911802 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR oslo_db.api
Aug 14 13:54:59.911951 ubuntu-xenial-citycloud-la1-10426313 neutron-server[13990]: ERROR neutron.pecan_wsgi.hooks.translation [None req-c66e03cb-f36a-494b-9f83-fcb51dd0a420 c_rally_732dd379_PVser3Et c_rally_732dd379_0ywBv9Oh] DELETE failed.: StaleDataError: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched.

[YAMAMOTO Takashi (yamamoto)]

Added neutron as it doesn't seem networking-midonet specific

[Ihar Hrachyshka (ihar-hrachyshka)]

Can we get a logstash link produced for that? It may help to understand how often it affects midonet. We don't see any major failure spikes in neutron gate for rally.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/492374
Committed: https://git.openstack.org/cgit/openstack/networking-midonet/commit/?id=0eba6c8bb436970307651f5b19358cd9e0627cbd
Submitter: Jenkins
Branch: master

commit 0eba6c8bb436970307651f5b19358cd9e0627cbd
Author: YAMAMOTO Takashi <email address hidden>
Date: Thu Aug 10 04:31:22 2017 +0000

    Revert "Disable custom plugin scenarios in rally"

    This reverts commit a487c8439d058004e5c0cf72c18ec348d658f8fa.

    Also,

    - Remove unused context from midonet scenarios.

    - Enlarge the subnet for for NetworkPlugin.create_routers to avoid
      "Unexpected error: increment exceeds address boundary!"

    - Comment out sla sections for some failing scenarios because their
      failure ratios seem too high for a voting job.

    Related-Bug: #1670577
    Related-Bug: #1710589
    Change-Id: I10f49177e64acb64820831f3f32eb26eca05f153

[Zachary Ma (mazengxie)]

In my environment,
The neutron-server log also prints the following error message.
"UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched."
[Logs]
4124:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api [req-3a38738f-efbf-45b0-ae65-3af84f6aae2c - - - - -] DB exceeded retry limit.: StaleDataError: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched.
4125:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api Traceback (most recent call last):
4126:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 138, in wrapper
4127:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api return f(*args, **kwargs)
4128:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 128, in wrapped
4129:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api LOG.debug("Retry wrapper got retriable exception: %s", e)
4130:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in _exit_
4131:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api self.force_reraise()
4132:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
4133:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api six.reraise(self.type_, self.value, self.tb)
4134:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 124, in wrapped
4135:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api return f(*dup_args, **dup_kwargs)
4136:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 1702, in update_port_statuses
4137:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api context, port_dbs_by_id[port_id], status, host)
4138:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 1714, in _safe_update_individual_port_db_status
4139:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api ectx.reraise = bool(db.get_port(context, port_id))
4140:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in _exit_
4141:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api self.force_reraise()
4142:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
4143:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api six.reraise(self.type_, self.value, self.tb)
4144:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 1710, in _safe_update_individual_port_db_status
4145:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api context, port, status, host)
4146:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 1769, in _update_individual_port_db_status
4147:2017-09-19 17:10:15.211 10600 ERROR oslo_db.api levels = db.get_binding_levels(context, port_id, host)
4148:2017-09-19 17:10:15.211 ...