test_security_group_rules_create_with_optional_arguments fails: This result object does not return rows. It has been closed automatically.

[Matt Riedemann]

http://logs.openstack.org/37/84037/8/check/check-grenade-dsvm-partial-ncpu/624ff48/console.html

2014-05-03 06:40:26.421 | FAIL: tempest.api.compute.security_groups.test_security_group_rules.SecurityGroupRulesTestJSON.test_security_group_rules_create_with_optional_arguments[gate,smoke]
2014-05-03 06:40:26.422 | tempest.api.compute.security_groups.test_security_group_rules.SecurityGroupRulesTestJSON.test_security_group_rules_create_with_optional_arguments[gate,smoke]
2014-05-03 06:40:26.422 | ----------------------------------------------------------------------
2014-05-03 06:40:26.422 | _StringException: Empty attachments:
2014-05-03 06:40:26.422 | stderr
2014-05-03 06:40:26.422 | stdout
2014-05-03 06:40:26.422 |
2014-05-03 06:40:26.422 | pythonlogging:'': {{{2014-05-03 06:33:11,606 Request (SecurityGroupRulesTestJSON:test_security_group_rules_create_with_optional_arguments): 500 POST http://127.0.0.1:8774/v2/b3e8d194e4154bde8bf4996164316d17/os-security-groups 0.081s}}}
2014-05-03 06:40:26.423 |
2014-05-03 06:40:26.423 | Traceback (most recent call last):
2014-05-03 06:40:26.423 | File "tempest/api/compute/security_groups/test_security_group_rules.py", line 59, in test_security_group_rules_create_with_optional_arguments
2014-05-03 06:40:26.423 | resp, security_group = self.create_security_group()
2014-05-03 06:40:26.423 | File "tempest/api/compute/base.py", line 195, in create_security_group
2014-05-03 06:40:26.423 | description)
2014-05-03 06:40:26.423 | File "tempest/services/compute/json/security_groups_client.py", line 64, in create_security_group
2014-05-03 06:40:26.423 | resp, body = self.post('os-security-groups', post_body)
2014-05-03 06:40:26.423 | File "tempest/common/rest_client.py", line 201, in post
2014-05-03 06:40:26.423 | return self.request('POST', url, extra_headers, headers, body)
2014-05-03 06:40:26.423 | File "tempest/common/rest_client.py", line 454, in request
2014-05-03 06:40:26.424 | resp, resp_body)
2014-05-03 06:40:26.424 | File "tempest/common/rest_client.py", line 550, in _error_checker
2014-05-03 06:40:26.424 | raise exceptions.ServerFault(message)
2014-05-03 06:40:26.424 | ServerFault: Got server fault
2014-05-03 06:40:26.424 | Details: The server has either erred or is incapable of performing the requested operation.

From the nova-api log:

http://logs.openstack.org/37/84037/8/check/check-grenade-dsvm-partial-ncpu/624ff48/logs/old/screen-n-api.txt.gz?level=TRACE#_2014-05-03_06_33_11_568

2014-05-03 06:33:11.568 ERROR nova.api.openstack [req-695ed8e3-e955-4aa2-be6d-89357fb6080e SecurityGroupRulesTestJSON-476959890 SecurityGroupRulesTestJSON-1336565511] Caught error: This result object does not return rows. It has been closed automatically.
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack Traceback (most recent call last):
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/api/openstack/__init__.py", line 125, in __call__
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack return req.get_response(self.application)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack application, catch_exc_info=False)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack app_iter = application(self.environ, start_response)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack return resp(environ, start_response)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/opt/stack/old/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 632, in __call__
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack return self.app(env, start_response)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack return resp(environ, start_response)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack return resp(environ, start_response)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack response = self.app(environ, start_response)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack return resp(environ, start_response)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack resp = self.call_func(req, *args, **self.kwargs)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack return self.func(req, *args, **kwargs)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/api/openstack/wsgi.py", line 917, in __call__
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack content_type, body, accept)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/api/openstack/wsgi.py", line 983, in _process_stack
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack action_result = self.dispatch(meth, request, action_args)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/api/openstack/wsgi.py", line 1070, in dispatch
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack return method(req=request, **action_args)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/api/openstack/compute/contrib/security_groups.py", line 315, in create
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack context, group_name, group_description)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/compute/api.py", line 3595, in create_security_group
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack reservations = QUOTAS.reserve(context, security_groups=1)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/quota.py", line 1270, in reserve
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack user_id=user_id)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/quota.py", line 513, in reserve
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack project_id=project_id, user_id=user_id)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/db/api.py", line 1105, in quota_reserve
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack project_id=project_id, user_id=user_id)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/db/sqlalchemy/api.py", line 164, in wrapper
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack return f(*args, **kwargs)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/db/sqlalchemy/api.py", line 202, in wrapped
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack return f(*args, **kwargs)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/db/sqlalchemy/api.py", line 3078, in quota_reserve
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack project_id, user_id)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/opt/stack/old/nova/nova/db/sqlalchemy/api.py", line 3036, in _get_user_quota_usages
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack with_lockmode('update').\
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2292, in all
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack return list(self)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/loading.py", line 65, in instances
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack fetch = cursor.fetchall()
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/result.py", line 788, in fetchall
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack self.cursor, self.context)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1111, in _handle_dbapi_exception
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack util.reraise(*exc_info)
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/result.py", line 782, in fetchall
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack l = self.process_rows(self._fetchall_impl())
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/result.py", line 751, in _fetchall_impl
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack self._non_result()
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/result.py", line 756, in _non_result
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack "This result object does not return rows. "
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack ResourceClosedError: This result object does not return rows. It has been closed automatically.
2014-05-03 06:33:11.568 7087 TRACE nova.api.openstack

Looks like it's a race with creating the quota.

message:"Caught error\: This result object does not return rows. It has been closed automatically." AND tags:screen-n-api.txt

8 hits in the last 7 days, all failures, check and gate:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiQ2F1Z2h0IGVycm9yXFw6IFRoaXMgcmVzdWx0IG9iamVjdCBkb2VzIG5vdCByZXR1cm4gcm93cy4gSXQgaGFzIGJlZW4gY2xvc2VkIGF1dG9tYXRpY2FsbHkuXCIgQU5EIHRhZ3M6c2NyZWVuLW4tYXBpLnR4dCIsImZpZWxkcyI6W10sIm9mZnNldCI6MCwidGltZWZyYW1lIjoiNjA0ODAwIiwiZ3JhcGhtb2RlIjoiY291bnQiLCJ0aW1lIjp7InVzZXJfaW50ZXJ2YWwiOjB9LCJzdGFtcCI6MTM5OTEyMTc3MjUyNX0=

[Matt Riedemann (mriedem)]

Looks like it started on 4/30 so we should look for security group or quota changes to nova around that time.

[Matt Riedemann (mriedem)]

e-r query patch: https://review.openstack.org/#/c/91958/

[Matt Riedemann (mriedem)]

Went through the commits around 4/30 and not seeing anything obvious.

[Matt Riedemann (mriedem)]

Sounds like it could be a concurrency issue with mysqldb and sqlalchemy:

https://groups.google.com/forum/#!topic/sqlalchemy/wVyUoXorFrE

And here is a thread on using with_lockmode('update') with mysql and sqlalchemy and that's what the quotas query is doing:

https://groups.google.com/forum/#!topic/sqlalchemy/MBRcTJzi8Kk

http://stackoverflow.com/questions/14375666/sqlalchemy-prevent-automatic-closing

Might need to see which version of sqlalchemy we're running with in the gate and see if there are any newer versions with bug fixes for the mysqldb engine.

[Joe Gordon (jogo)]

no hits anymore looks like this was resolved somehow.