Bug 1369722 - Trace errors during rally task create_and_delete_routers.json
Summary: Trace errors during rally task create_and_delete_routers.json
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-neutron
Version: 7.0 (Kilo)
Hardware: Unspecified
OS: Unspecified
medium
high
Target Milestone: async
: 7.0 (Kilo)
Assignee: Ihar Hrachyshka
QA Contact: Toni Freger
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-08-24 08:44 UTC by Eran Kuris
Modified: 2017-02-15 13:50 UTC (History)
9 users (show)

Fixed In Version: openstack-neutron-2015.1.4-12.el7ost
Doc Type: Bug Fix
Doc Text:
Prior to this update, data database layer errors were not caught by the server component, resulting in errors during port status update requests (for particular race conditions). Consequently, on occasion, an L2 agent that attempted to update a port status could have caught an unexpected error from neutron-server, triggering a costly full resync of port data. With this update, neutron-server now correctly catches the previously missed error and repeats the failed operation. As a result, the L2 agent is no longer exposed to the unexpected error, and will not trigger full resync in this particular scenario.
Clone Of:
Environment:
Last Closed: 2017-02-15 13:50:35 UTC
Target Upstream Version:

Attachments (Terms of Use)
logs (12.02 KB, text/plain)
2016-08-24 08:46 UTC, Eran Kuris 		no flags Details
View All Add an attachment (proposed patch, testcase, etc.)


Links
System ID Private Priority Status Summary Last Updated
OpenStack gerrit 192063 0 None None None 2016-09-20 12:55:52 UTC
Red Hat Product Errata RHBA-2017:0277 0 normal SHIPPED_LIVE openstack-neutron bug fix advisory 2017-02-15 18:49:17 UTC

Description Eran Kuris 2016-08-24 08:44:13 UTC 
Description of problem:
Ran rally task on RHOS7 HA env 


in neutron server log I found those trace errors 
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher Traceback (most recent call last):
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 142, in _dispatch_and_reply
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     executor_callback))
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 186, in _dispatch
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     executor_callback)
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 130, in _do_dispatch
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     result = func(ctxt, **new_args)
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/rpc.py", line 134, in get_devices_details_list
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     for device in kwargs.pop('devices', [])
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/rpc.py", line 106, in get_device_details
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     host)
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 131, in wrapper
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     return f(*args, **kwargs)
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 1388, in update_port_status
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     original_port['network_id'])
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 653, in get_network
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     result = super(Ml2Plugin, self).get_network(context, id, None)
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/neutron/db/db_base_plugin_v2.py", line 1022, in get_network
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     network = self._get_network(context, id)
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/neutron/db/db_base_plugin_v2.py", line 91, in _get_network
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     network = self._get_by_id(context, models_v2.Network, id)
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib/python2.7/site-packages/neutron/db/common_db_mixin.py", line 171, in _get_by_id
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     return query.filter(model.id == id).one()
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2473, in one
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     ret = list(self)
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2515, in __iter__
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     self.session._autoflush()
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 1282, in _autoflush
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     self.flush()
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 2004, in flush
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     self._flush(objects)
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 2122, in _flush
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     transaction.rollback(_capture_exception=True)
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     compat.reraise(exc_type, exc_value, exc_tb)
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 2086, in _flush
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     flush_context.execute()
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 373, in execute
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     rec.execute(self)
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 532, in execute
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     uow
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 170, in save_obj
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     mapper, table, update)
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 712, in _emit_update_statements
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher     (table.description, len(records), rows))
2016-08-23 13:12:20.271 27891 TRACE oslo_messaging.rpc.dispatcher StaleDataError: UPDATE statement on table 'ports' expected to update 1 row(s); 0 were matched.

Version-Release number of selected component (if applicable):

openstack-neutron-2015.1.4-3.el7ost.noarch
openstack-neutron-ml2-2015.1.4-3.el7ost.noarch
python-neutron-2015.1.4-3.el7ost.noarch
openstack-neutron-common-2015.1.4-3.el7ost.noarch
openstack-neutron-openvswitch-2015.1.4-3.el7ost.noarch
python-neutronclient-2.4.0-2.el7ost.noarch

How reproducible:


Steps to Reproduce:
1. deploy rhos 7 HA  (virtual setup)
2. run rally test : create_and_delete_routers.json 
3. check server log 

Actual results:


Expected results:


Additional info:
Comment 2 Eran Kuris 2016-08-24 08:46:10 UTC 
Created attachment 1193544 [details]
logs
Comment 3 Jakub Libosvar 2016-08-24 08:47:18 UTC 
Was there any impact of the trace? Has anything failed?
Comment 4 John Schwarz 2016-08-24 08:50:29 UTC 
The rally tests showed 100% success rate for 'rally task detailed' of that run, and no ports were left afterwards. I didn't find any other side effects as well, though you might have better ideas.
Comment 6 Miguel Angel Ajo 2016-09-06 11:52:42 UTC 
Looks like if a the status of a port is concurrently updated from two places, and 2nd fails.

I'd like to have a look on the ovs agent which called that get_devices_details_list (which in turns triggers the port update).

Seeing 100% success on the test, I assume that the ovs-agent gets the failed call and triggers a full-sync with the server, recovering from the condition.
Comment 7 Hynek Mlnarik 2016-09-06 12:29:18 UTC 
The StaleDataError issue is harmless and seems same as bug 1348998. See there for details, namely comments 2 and 3. The StaleDataError impact was mitigated in liberty by retrying the operation.
Comment 10 Toni Freger 2017-02-14 15:11:03 UTC 
The code is verified on latest OSP7 - openstack-neutron-2015.1.4-12.el7ost.noarch
Comment 12 errata-xmlrpc 2017-02-15 13:50:35 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2017-0277.html
Note You need to log in before you can comment on or make changes to this bug.