StaleDataError: DELETE statement on table 'standardattributes' expected to delete 1 row(s); 0 were matched

[Ihar Hrachyshka]

This error started to show up in neutron-server logs in gate after https://review.openstack.org/#/c/328185/5 landed. The reason is that using version_id_col makes UPDATE and DELETE filter by the revision number, and raise StaleDataError on mismatch. That's documented in: http://docs.sqlalchemy.org/en/latest/orm/exceptions.html#sqlalchemy.orm.exc.StaleDataError

Once the exception is raised, it's correctly caught by retry mechanism. We should consider StateDataErrors a usual operation mode, and hence avoid logging the exceptions in ml2 plugin. Instead, we should bubble up exceptions to retry layer and allow it to determine if to log those exceptions.

[Ihar Hrachyshka (ihar-hrachyshka)]

http://logs.openstack.org/51/327651/5/gate/gate-tempest-dsvm-neutron-dvr/fa16047/logs/screen-q-svc.txt.gz#_2016-06-17_11_24_53_940

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/334367

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/331137
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=f3816cb8bd68f406d7f8c5b80fbd3352b493ca70
Submitter: Jenkins
Branch: master

commit f3816cb8bd68f406d7f8c5b80fbd3352b493ca70
Author: Ihar Hrachyshka <email address hidden>
Date: Wed Jun 29 15:35:44 2016 +0200

    ml2: postpone exception logs to when retry mechanism fails to recover

    Since Ia2d911a6a90b1baba1d5cc36f7c625e156a2bc33, we use version_id_col
    SQLAlchemy feature to routinely bump revision numbers for resources. By
    doing so, SQLAlchemy also enforces the expected number on any UPDATE and
    DELETE, which may not be valid when the transaction is actually applied.
    In that case, the library will raise StaleDataError:

    http://docs.sqlalchemy.org/en/latest/orm/exceptions.html#sqlalchemy.orm.exc.StaleDataError

    The exception is then logged by ml2 and bubbles up to API layer where
    retry mechanism will correctly catch it and issue another attempt.

    If API layer does not retry on exception, it already logs the error,
    including the traceback.

    In ml2, it's too early to decide if an exception is worth being logged.
    Plugin instead should just silently allow all unexpected exceptions to
    bubble up and be dealt by API layer.

    At the same time, there are some details that are known at the plugin
    level only, that are not easily deducible from the API request details.
    That's why we save details about the error on the exception object that
    bubbles up into API layer, where we are ready to decide if those details
    are worth being logged.

    Change-Id: I848df0aef5381e50dfb58e46d7a652113ac27a49
    Closes-Bug: #1593719

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/neutron 9.0.0.0b2 development milestone.

[OpenStack Infra (hudson-openstack)]

Change abandoned by Ihar Hrachyshka (<email address hidden>) on branch: master
Review: https://review.openstack.org/334367

[Ihar Hrachyshka (ihar-hrachyshka)]

Only N is affected.

[Zachary Ma (mazengxie)]

Still have this problem in Pike.
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api [req-3335edae-590d-4790-b439-82a199292813 - - - - -] DB exceeded retry limit.: StaleDataError: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched.
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api Traceback (most recent call last):
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 138, in wrapper
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api return f(*args, **kwargs)
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 128, in wrapped
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api LOG.debug("Retry wrapper got retriable exception: %s", e)
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api self.force_reraise()
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api six.reraise(self.type_, self.value, self.tb)
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 124, in wrapped
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api return f(*dup_args, **dup_kwargs)
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 1702, in update_port_statuses
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api context, port_dbs_by_id[port_id], status, host)
2017-09-20 15:38:42.368 2116 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
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api ectx.reraise = bool(db.get_port(context, port_id))
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api self.force_reraise()
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api six.reraise(self.type_, self.value, self.tb)
2017-09-20 15:38:42.368 2116 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
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api context, port, status, host)
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 1769, in _update_individual_port_db_status
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api levels = db.get_binding_levels(context, port_id, host)
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api File "/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 979, in wrapper
2017-09-20 15:38:42.368 2116 ERROR oslo_db.api return fn(*args, **kwargs)
2017-09-20 15:38:42.368 2116 E...

[shihanzhang (shihanzhang)]

i have same problem with this patch:https://review.openstack.org/#/c/503517/, and this problem will lead to incorrect ovs flow pipline for dvr on compute node.