Neutron failed to create network

[Ivan Lozgachev]

MOS 9.0 RC2 build 495

Detailed problem observation:
During Rally test NeutronNetworks.create_and_list_routers neutron client throwed exception

InternalServerError: Request Failed: internal server error while processing your request.
Neutron server returns request_ids: ['req-e6542049-3c40-4813-989b-c142891ffc96']

From neutron logs:

<163>Jun 22 15:00:15 node-1 neutron-server: 2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource [req-e6542049-3c40-4813-989b-c142891ffc96 439a0f4df8e2496e92c3ea28594db1ad 715e0178f50247baa3c55af1a8f68bdd - - -] create failed
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource Traceback (most recent call last):
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/api/v2/resource.py", line 84, in resource
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource result = method(request=request, **args)
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/api/v2/base.py", line 410, in create
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource return self._create(request, body, **kwargs)
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/oslo_db/api.py", line 148, in wrapper
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource ectxt.value = e.inner_exc
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource self.force_reraise()
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource six.reraise(self.type_, self.value, self.tb)
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/oslo_db/api.py", line 138, in wrapper
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource return f(*args, **kwargs)
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/api/v2/base.py", line 521, in _create
2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource obj = do_create(body)
2016-06-22 15:00:15.516 23028

Actual result: failed Rally iteration
Expected result: no fails
Seen only one time

Fuel snapshot http://mos-scale-share.mirantis.com/fuel-snapshot-2016-06-23_10-25-08.tar.gz

[Bug Checker Bot (bug-checker)]

(This check performed automatically)
Please, make sure that bug description contains the following sections filled in with the appropriate data related to the bug you are describing:

version

steps to reproduce

For more detailed information on the contents of each of the listed sections see https://wiki.openstack.org/wiki/Fuel/How_to_contribute#Here_is_how_you_file_a_bug

[Oleg Bondarev (obondarev)]

Can you please include full traceback to the description? Currently it doesn't even show what the Error is. I see snapshot attached but full tracebacks would really help triaging bugs

[Eugene Nikanorov (enikanorov)]

2016-06-22 15:00:15.516 23028 ERROR neutron.api.v2.resource OperationalError: (_mysql_exceptions.OperationalError) (1305, 'SAVEPOINT sa_savepoint_1 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_1']

On security group creation during network creation.
And here we go again

[Alexander Ignatov (aignatov)]

This script reproduce similar exception which Eugene mentioned above:

http://paste.openstack.org/show/562439/

Looks like a bug in sqlalchemy:

https://bitbucket.org/zzzeek/sqlalchemy/issues/2696/misleading-exception-triggered-on

[Alexander Ignatov (aignatov)]

Traceback generated by script above:

(myenv) ➜ myenv python new_script.py
2016-08-23 13:41:26,665 INFO sqlalchemy.engine.base.Engine SHOW VARIABLES LIKE 'sql_mode'
2016-08-23 13:41:26,665 INFO sqlalchemy.engine.base.Engine {}
2016-08-23 13:41:26,668 INFO sqlalchemy.engine.base.Engine SELECT DATABASE()
2016-08-23 13:41:26,668 INFO sqlalchemy.engine.base.Engine {}
2016-08-23 13:41:26,671 INFO sqlalchemy.engine.base.Engine show collation where `Charset` = 'utf8' and `Collation` = 'utf8_bin'
2016-08-23 13:41:26,671 INFO sqlalchemy.engine.base.Engine {}
2016-08-23 13:41:26,673 INFO sqlalchemy.engine.base.Engine SELECT CAST('test plain returns' AS CHAR(60)) AS anon_1
2016-08-23 13:41:26,673 INFO sqlalchemy.engine.base.Engine {}
2016-08-23 13:41:26,675 INFO sqlalchemy.engine.base.Engine SELECT CAST('test unicode returns' AS CHAR(60)) AS anon_1
2016-08-23 13:41:26,675 INFO sqlalchemy.engine.base.Engine {}
2016-08-23 13:41:26,676 INFO sqlalchemy.engine.base.Engine SELECT CAST('test collated returns' AS CHAR CHARACTER SET utf8) COLLATE utf8_bin AS anon_1
2016-08-23 13:41:26,676 INFO sqlalchemy.engine.base.Engine {}
2016-08-23 13:41:26,677 INFO sqlalchemy.engine.base.Engine DESCRIBE `a`
2016-08-23 13:41:26,677 INFO sqlalchemy.engine.base.Engine {}
2016-08-23 13:41:26,685 INFO sqlalchemy.engine.base.Engine ROLLBACK
2016-08-23 13:41:26,686 INFO sqlalchemy.engine.base.Engine DESCRIBE `a`
2016-08-23 13:41:26,686 INFO sqlalchemy.engine.base.Engine {}
2016-08-23 13:41:26,687 INFO sqlalchemy.engine.base.Engine ROLLBACK
2016-08-23 13:41:26,688 INFO sqlalchemy.engine.base.Engine
CREATE TABLE a (
        id INTEGER NOT NULL,
        PRIMARY KEY (id)
)

2016-08-23 13:41:26,688 INFO sqlalchemy.engine.base.Engine {}
2016-08-23 13:41:26,741 INFO sqlalchemy.engine.base.Engine COMMIT
2016-08-23 13:41:26,742 INFO sqlalchemy.engine.base.Engine BEGIN (implicit)
2016-08-23 13:41:26,742 INFO sqlalchemy.engine.base.Engine SAVEPOINT sa_savepoint_1
2016-08-23 13:41:26,742 INFO sqlalchemy.engine.base.Engine {}
2016-08-23 13:41:26,743 INFO sqlalchemy.engine.base.Engine rollback
2016-08-23 13:41:26,743 INFO sqlalchemy.engine.base.Engine {}
2016-08-23 13:41:26,745 INFO sqlalchemy.engine.base.Engine INSERT INTO a () VALUES ()
2016-08-23 13:41:26,745 INFO sqlalchemy.engine.base.Engine {}
/Users/aignatov/work/myenv/lib/python2.7/site-packages/pymysql/cursors.py:167: Warning: (1364, "Field 'id' doesn't have a default value")
  result = self._query(query)
2016-08-23 13:41:26,752 INFO sqlalchemy.engine.base.Engine ROLLBACK TO SAVEPOINT sa_savepoint_1
2016-08-23 13:41:26,752 INFO sqlalchemy.engine.base.Engine {}
/Users/aignatov/work/myenv/lib/python2.7/site-packages/sqlalchemy/orm/session.py:430: SAWarning: An exception raised during a Session persistence operation cannot be raised due to an additional ROLLBACK exception; the exception is: Instance <A at 0x104a5e650> has a NULL identity key. If this is an auto-generated value, check that the database table allows generation of new primary key values, and that the mapped Column object is configured to expect these generated values. Ensure also that this flush() is not occurring at an inappropriate time, such aswithin a load() event.
...

[Alexander Ignatov (aignatov)]

Full exception in neutron-server-1 from node-1, taken from snapshot:
http://paste.openstack.org/show/562448/

Traceback is similar to what we have in comment #5.

[Alexander Ignatov (aignatov)]

The only way here is to update sqlalchemy to a higher version to catch original exception which is currently being interrupted by exception during attempt to do rollback. To be more precise, this fix will help with further investigations which is in sqlalchemy==1.0.12:

https://bitbucket.org/zzzeek/sqlalchemy/commits/8a1e619fb20df1be6ad2e0c563e451e17eb17628#chg-lib/sqlalchemy/util/langhelpers.py

[Alexander Ignatov (aignatov)]

Hmm, now I've realized that in mos 9.0 we already use sqlalchemy==1.0.12 but still it's not clear why we don't see this specified WARNING in neutron logs:

https://bitbucket.org/zzzeek/sqlalchemy/commits/8a1e619fb20df1be6ad2e0c563e451e17eb17628#chg-lib/sqlalchemy/util/langhelpers.py

[Alexander Ignatov (aignatov)]

Looks like Kevin's fix should help with SAVEPOINT error.

[Alexander Ignatov (aignatov)]

https://review.openstack.org/#/c/326927/

[Alexander Ignatov (aignatov)]

Looks like we'll be able to fix this by adding pymsql driver first than backport Kevin's patch.

[Alexander Ignatov (aignatov)]

Since we are not going to put "pymysql" driver as defualt driver in mos, moving this issue to 9.2.

[Alexander Ignatov (aignatov)]

No plans to fix it in 9.2 by moving MOS to pymysql driver, targeting this bug to 10.0