yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1787028] Re: neutron returned internal server error on updating tags

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: hongbin <hongbin034@xxxxxxxxx>
Date: Mon, 06 May 2019 02:59:42 -0000
Reply-to: Bug 1787028 <1787028@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Changed in: kuryr-libnetwork
       Status: New => 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/1787028

Title:
  neutron returned internal server error on updating tags

Status in kuryr-libnetwork:
  Fix Released
Status in neutron:
  Fix Released

Bug description:
  Starting from Aug 14, 2018, kuryr-libnetwork's gate failed often with
  the following error:

  * job-output.txt.gz:

  2018-08-14 20:27:14.391592 | primary | 2018-08-14 20:27:14.390 | {3} kuryr_libnetwork.tests.fullstack.test_ipam.IpamTest.test_container_ipam_release_address_with_existing_network [6.935607s] ... FAILED
  2018-08-14 20:27:14.393446 | primary | 2018-08-14 20:27:14.392 |
  2018-08-14 20:27:14.394830 | primary | 2018-08-14 20:27:14.394 | Captured traceback:
  2018-08-14 20:27:14.396797 | primary | 2018-08-14 20:27:14.396 | ~~~~~~~~~~~~~~~~~~~
  2018-08-14 20:27:14.398457 | primary | 2018-08-14 20:27:14.398 |     Traceback (most recent call last):
  2018-08-14 20:27:14.401028 | primary | 2018-08-14 20:27:14.400 |       File "kuryr_libnetwork/tests/fullstack/test_ipam.py", line 295, in test_container_ipam_release_address_with_existing_network
  2018-08-14 20:27:14.403113 | primary | 2018-08-14 20:27:14.402 |         ipam=fake_ipam)
  2018-08-14 20:27:14.405412 | primary | 2018-08-14 20:27:14.404 |       File "/opt/stack/new/kuryr-libnetwork/.tox/fullstack/local/lib/python2.7/site-packages/docker/api/network.py", line 152, in create_network
  2018-08-14 20:27:14.407611 | primary | 2018-08-14 20:27:14.406 |         return self._result(res, json=True)
  2018-08-14 20:27:14.409240 | primary | 2018-08-14 20:27:14.408 |       File "/opt/stack/new/kuryr-libnetwork/.tox/fullstack/local/lib/python2.7/site-packages/docker/api/client.py", line 235, in _result
  2018-08-14 20:27:14.411630 | primary | 2018-08-14 20:27:14.410 |         self._raise_for_status(response)
  2018-08-14 20:27:14.414334 | primary | 2018-08-14 20:27:14.412 |       File "/opt/stack/new/kuryr-libnetwork/.tox/fullstack/local/lib/python2.7/site-packages/docker/api/client.py", line 231, in _raise_for_status
  2018-08-14 20:27:14.415967 | primary | 2018-08-14 20:27:14.415 |         raise create_api_error_from_http_exception(e)
  2018-08-14 20:27:14.417995 | primary | 2018-08-14 20:27:14.417 |       File "/opt/stack/new/kuryr-libnetwork/.tox/fullstack/local/lib/python2.7/site-packages/docker/errors.py", line 31, in create_api_error_from_http_exception
  2018-08-14 20:27:14.419630 | primary | 2018-08-14 20:27:14.419 |         raise cls(e, response=response, explanation=explanation)
  2018-08-14 20:27:14.422378 | primary | 2018-08-14 20:27:14.421 |     docker.errors.APIError: 500 Server Error: Internal Server Error ("NetworkDriver.CreateNetwork: Request Failed: internal server error while processing your request.
  2018-08-14 20:27:14.424519 | primary | 2018-08-14 20:27:14.423 |     Neutron server returns request_ids: ['req-d0268850-9176-4fad-a645-d772b462c36c']")
  2018-08-14 20:27:14.426527 | primary | 2018-08-14 20:27:14.426 |

  * screen-kuryr-libnetwork.txt

  Aug 14 20:27:13.549051 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]: 2018-08-14 20:27:13.543 4761 ERROR kuryr_libnetwork.utils [-] Unexpected error happened: Request Failed: internal server error while processing your request.
  Aug 14 20:27:13.549258 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]: Neutron server returns request_ids: ['req-d0268850-9176-4fad-a645-d772b462c36c']: InternalServerError: Request Failed: internal server error while processing your request.
  Aug 14 20:27:13.549461 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]: Traceback (most recent call last):
  Aug 14 20:27:13.549655 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:   File "/usr/local/lib/python2.7/dist-packages/flask/app.py", line 1813, in full_dispatch_request
  Aug 14 20:27:13.549889 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:     rv = self.dispatch_request()
  Aug 14 20:27:13.550118 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:   File "/usr/local/lib/python2.7/dist-packages/flask/app.py", line 1799, in dispatch_request
  Aug 14 20:27:13.550358 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:     return self.view_functions[rule.endpoint](**req.view_args)
  Aug 14 20:27:13.550606 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:   File "/opt/stack/new/kuryr-libnetwork/kuryr_libnetwork/controllers.py", line 900, in network_driver_create_network
  Aug 14 20:27:13.550858 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:     _neutron_net_add_tags(network_id, container_net_id, tags=app.tag)
  Aug 14 20:27:13.551107 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:   File "/opt/stack/new/kuryr-libnetwork/kuryr_libnetwork/controllers.py", line 345, in _neutron_net_add_tags
  Aug 14 20:27:13.551341 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:     _neutron_net_add_tag(netid, tag)
  Aug 14 20:27:13.551553 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:   File "/opt/stack/new/kuryr-libnetwork/kuryr_libnetwork/controllers.py", line 338, in _neutron_net_add_tag
  Aug 14 20:27:13.551768 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:     _neutron_add_tag('networks', netid, tag)
  Aug 14 20:27:13.552016 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:   File "/opt/stack/new/kuryr-libnetwork/kuryr_libnetwork/controllers.py", line 384, in _neutron_add_tag
  Aug 14 20:27:13.552277 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:     app.neutron.add_tag(resource_type, resource_id, tag)
  Aug 14 20:27:13.552521 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:   File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 2075, in add_tag
  Aug 14 20:27:13.558223 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:     return self.put(self.tag_path % (resource_type, resource_id, tag))
  Aug 14 20:27:13.558449 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:   File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 363, in put
  Aug 14 20:27:13.558650 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:     headers=headers, params=params)
  Aug 14 20:27:13.558866 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:   File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 331, in retry_request
  Aug 14 20:27:13.559101 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:     headers=headers, params=params)
  Aug 14 20:27:13.559340 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:   File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 294, in do_request
  Aug 14 20:27:13.559563 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:     self._handle_fault_response(status_code, replybody, resp)
  Aug 14 20:27:13.559772 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:   File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 269, in _handle_fault_response
  Aug 14 20:27:13.559995 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:     exception_handler_v20(status_code, error_body)
  Aug 14 20:27:13.560197 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:   File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 93, in exception_handler_v20
  Aug 14 20:27:13.560353 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]:     request_ids=request_ids)
  Aug 14 20:27:13.560530 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]: InternalServerError: Request Failed: internal server error while processing your request.
  Aug 14 20:27:13.560680 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]: Neutron server returns request_ids: ['req-d0268850-9176-4fad-a645-d772b462c36c']
  Aug 14 20:27:13.560886 ubuntu-xenial-inap-mtl01-0001325098 kuryr-server[4761]: 2018-08-14 20:27:13.549 4761 INFO werkzeug [-] 127.0.0.1 - - [14/Aug/2018 20:27:13] "POST /NetworkDriver.CreateNetwork HTTP/1.1" 500 -

  * screen-q-svc.txt

  Aug 14 20:27:13.540531 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource [None req-d0268850-9176-4fad-a645-d772b462c36c service kuryr] update failed: No details.: StaleDataError: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched.
  Aug 14 20:27:13.540720 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource Traceback (most recent call last):
  Aug 14 20:27:13.540898 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/opt/stack/new/neutron/neutron/api/v2/resource.py", line 98, in resource
  Aug 14 20:27:13.541108 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     result = method(request=request, **args)
  Aug 14 20:27:13.541309 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/opt/stack/new/neutron/neutron/extensions/tagging.py", line 122, in update
  Aug 14 20:27:13.541513 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     result = self.plugin.update_tag(request.context, parent, parent_id, id)
  Aug 14 20:27:13.541719 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/oslo_log/helpers.py", line 67, in wrapper
  Aug 14 20:27:13.541925 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     return method(*args, **kwargs)
  Aug 14 20:27:13.542131 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/opt/stack/new/neutron/neutron/services/tag/tag_plugin.py", line 116, in update_tag
  Aug 14 20:27:13.542386 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     tag=tag).create()
  Aug 14 20:27:13.542613 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/opt/stack/new/neutron/neutron/objects/base.py", line 315, in decorator
  Aug 14 20:27:13.542855 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     return func(self, *args, **kwargs)
  Aug 14 20:27:13.543086 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/opt/stack/new/neutron/neutron/objects/base.py", line 769, in create
  Aug 14 20:27:13.543331 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     self, self.obj_context, self.modify_fields_to_db(fields))
  Aug 14 20:27:13.543555 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/opt/stack/new/neutron/neutron/objects/db/api.py", line 63, in create_object
  Aug 14 20:27:13.543771 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     context.session.add(db_obj)
  Aug 14 20:27:13.543989 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
  Aug 14 20:27:13.544246 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     self.gen.next()
  Aug 14 20:27:13.544512 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/neutron_lib/db/api.py", line 199, in autonested_transaction
  Aug 14 20:27:13.544749 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     yield tx
  Aug 14 20:27:13.544987 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 572, in __exit__
  Aug 14 20:27:13.545212 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     self.rollback()
  Aug 14 20:27:13.545400 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 66, in __exit__
  Aug 14 20:27:13.545640 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     compat.reraise(exc_type, exc_value, exc_tb)
  Aug 14 20:27:13.545819 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 569, in __exit__
  Aug 14 20:27:13.546077 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     self.commit()
  Aug 14 20:27:13.546311 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 467, in commit
  Aug 14 20:27:13.546523 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     self._prepare_impl()
  Aug 14 20:27:13.546732 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 436, in _prepare_impl
  Aug 14 20:27:13.546991 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     self.session.dispatch.before_commit(self.session)
  Aug 14 20:27:13.547223 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/event/attr.py", line 246, in __call__
  Aug 14 20:27:13.547437 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     fn(*args, **kw)
  Aug 14 20:27:13.547648 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/neutron_lib/db/api.py", line 316, in _load_one_to_manys
  Aug 14 20:27:13.547819 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     session.flush()
  Aug 14 20:27:13.548014 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2254, in flush
  Aug 14 20:27:13.548197 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     self._flush(objects)
  Aug 14 20:27:13.552767 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2380, in _flush
  Aug 14 20:27:13.553037 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     transaction.rollback(_capture_exception=True)
  Aug 14 20:27:13.553260 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 66, in __exit__
  Aug 14 20:27:13.553503 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     compat.reraise(exc_type, exc_value, exc_tb)
  Aug 14 20:27:13.553764 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2344, in _flush
  Aug 14 20:27:13.554255 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     flush_context.execute()
  Aug 14 20:27:13.554546 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 391, in execute
  Aug 14 20:27:13.554774 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     rec.execute(self)
  Aug 14 20:27:13.555115 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 556, in execute
  Aug 14 20:27:13.555799 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     uow
  Aug 14 20:27:13.556067 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 177, in save_obj
  Aug 14 20:27:13.556317 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     mapper, table, update)
  Aug 14 20:27:13.556543 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 791, in _emit_update_statements
  Aug 14 20:27:13.557347 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource     (table.description, len(records), rows))
  Aug 14 20:27:13.557557 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource StaleDataError: UPDATE statement on table 'standardattributes' expected to update 1 row(s); 0 were matched.
  Aug 14 20:27:13.557743 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: ERROR neutron.api.v2.resource 
  Aug 14 20:27:13.561375 ubuntu-xenial-inap-mtl01-0001325098 neutron-server[25320]: INFO neutron.wsgi [None req-d0268850-9176-4fad-a645-d772b462c36c service kuryr] 198.72.124.15 "PUT /v2.0/networks/e658851d-a85d-48a4-9635-3d517dc58b6e/tags/kuryr.net.uuid.lh:caa6ea05f9fae965c1d8e3aa76ad1faf HTTP/1.1" status: 500  len: 368 time: 1.2829261

To manage notifications about this bug go to:
https://bugs.launchpad.net/kuryr-libnetwork/+bug/1787028/+subscriptions
References

[Bug 1787028] [NEW] neutron returned internal server error on updating tags
From: Hongbin Lu, 2018-08-14